Repository: fortio/fortio (go)

Issue:
fortio access log doesn't show success vs error requests

Pull request description:
Track success vs failure, add that and details string for richer access log, visualize new errors histogram
- [x] richer access log (with success/failure boolean and details)
- [x] use it in runner results: additional histogram of error cases
- [x] show it in report ui

Looks like this:

<img width="1828" alt="Screen Shot 2022-04-24 at 4 32 03 PM" src="https://user-images.githubusercontent.com/3664595/165001248-33e180d5-fd6b-4389-b73e-79a21e76d5b0.png">

With text output:
```
Starting at 1000 qps with 8 thread(s) [gomax 10] for 3s : 375 calls each (total 3000)
Ended after 3.012998625s : 1811 calls. qps=601.06
Sleep times : count 1803 avg 0.0068899165 +/- 0.001709 min 1.7011e-05 max 0.007993206 sum 12.4225194
Aggregated Function Time : count 1811 avg 0.0062169943 +/- 0.01646 min 0.00010075 max 0.12141675 sum 11.2589767
# range, mid point, percentile, count
>= 0.00010075 <= 0.0002 , 0.000150375 , 31.92, 578
> 0.0002 <= 0.0003 , 0.00025 , 53.40, 389
> 0.0003 <= 0.0004 , 0.00035 , 55.60, 40
> 0.0004 <= 0.0005 , 0.00045 , 68.97, 242
> 0.0005 <= 0.0006 , 0.00055 , 79.79, 196
> 0.0006 <= 0.0007 , 0.00065 , 81.39, 29
> 0.0007 <= 0.0008 , 0.00075 , 81.94, 10
> 0.0008 <= 0.0009 , 0.00085 , 82.33, 7
> 0.0009 <= 0.001 , 0.00095 , 82.55, 4
> 0.001 <= 0.0011 , 0.00105 , 82.72, 3
> 0.0011 <= 0.0012 , 0.00115 , 82.83, 2
> 0.0012 <= 0.0014 , 0.0013 , 83.10, 5
> 0.0014 <= 0.0016 , 0.0015 , 83.21, 2
> 0.002 <= 0.0025 , 0.00225 , 83.38, 3
> 0.005 <= 0.006 , 0.0055 , 87.58, 76
> 0.007 <= 0.008 , 0.0075 , 87.63, 1
> 0.03 <= 0.035 , 0.0325 , 88.68, 19
> 0.035 <= 0.04 , 0.0375 , 94.20, 100
> 0.04 <= 0.045 , 0.0425 , 97.57, 61
> 0.045 <= 0.05 , 0.0475 , 98.18, 11
> 0.05 <= 0.06 , 0.055 , 98.23, 1
> 0.07 <= 0.08 , 0.075 , 99.06, 15
> 0.08 <= 0.09 , 0.085 , 99.56, 9
> 0.1 <= 0.121417 , 0.110708 , 100.00, 8
# target 50% 0.00028419
# target 75% 0.00055574
# target 90% 0.036195
# target 99% 0.07926
# target 99.9% 0.116569
Error cases : count 33 avg 0.0056101022 +/- 0.01298 min 0.000140792 max 0.045081625 sum 0.185133373
# range, mid point, percentile, count
>= 0.000140792 <= 0.0002 , 0.000170396 , 15.15, 5
> 0.0002 <= 0.0003 , 0.00025 , 48.48, 11
> 0.0003 <= 0.0004 , 0.00035 , 57.58, 3
> 0.0004 <= 0.0005 , 0.00045 , 66.67, 3
> 0.0005 <= 0.0006 , 0.00055 , 72.73, 2
> 0.0006 <= 0.0007 , 0.00065 , 78.79, 2
> 0.005 <= 0.006 , 0.0055 , 87.88, 3
> 0.035 <= 0.04 , 0.0375 , 93.94, 2
> 0.04 <= 0.045 , 0.0425 , 96.97, 1
> 0.045 <= 0.0450816 , 0.0450408 , 100.00, 1
# target 50% 0.000316667
# target 75% 0.0006375
# target 90% 0.03675
# target 99% 0.0450547
# target 99.9% 0.0450789
Sockets used: 41 (for perfect keepalive, would be 8)
Uniform: true, Jitter: false
Code 200 : 1778 (98.2 %)
Code 429 : 26 (1.4 %)
Code 503 : 7 (0.4 %)
Response Header Sizes : count 1811 avg 73.633352 +/- 10.03 min 0 max 75 sum 133350
Response Body/Total Sizes : count 1811 avg 75.28106 +/- 2.066 min 75 max 92 sum 136334
Saved result to [data/2022-04-24-163139_4_Fortio.json](http://localhost:8080/fortio/data/2022-04-24-163139_4_Fortio.json) ([graph link](http://localhost:8080/fortio/browse?url=2022-04-24-163139_4_Fortio.json))
All done 1811 calls 6.217 ms avg, 601.1 qps
```

fixes #553

Patch:
diff --git a/.circleci/config.yml b/.circleci/config.yml
index eda2995..75bbbbb 100644
--- a/.circleci/config.yml
+++ b/.circleci/config.yml
@@ -22,10 +22,7 @@ jobs:
       - setup_remote_docker:
           version: 20.10.12
       - checkout
-      - run: |
-          docker context create release-tests
-          docker buildx create release-tests --use
-          make release-test BUILDX_PLATFORMS=linux/amd64
+      - run: make release-test
   linters:
     <<: *defaultEnv
     steps:
diff --git a/Makefile b/Makefile
index ab45b8e..a5a9495 100755
--- a/Makefile
+++ b/Makefile
@@ -109,6 +109,9 @@ update-build-image-tag:
 	@echo 'Need to use gnu sed (brew install gnu-sed; make update-build-image-tag SED=gsed)'
 	$(SED) --in-place=.bak -e 's!$(DOCKER_PREFIX).build:v..!$(BUILD_IMAGE)!g' $(FILES_WITH_IMAGE)
 
+docker-default-platform:
+	@docker buildx --builder default inspect | tail -1 | sed -e "s/Platforms: //" -e "s/,//g" | awk '{print $$1}'
+
 docker-version:
 	@echo "### Docker is `which docker`"
 	@docker version
diff --git a/README.md b/README.md
index 100d4d0..685357c 100644
--- a/README.md
+++ b/README.md
@@ -50,13 +50,13 @@ You can install from source:
 
 
 ```shell
-curl -L https://github.com/fortio/fortio/releases/download/v1.27.0/fortio-linux_amd64-1.27.0.tgz \
+curl -L https://github.com/fortio/fortio/releases/download/v1.28.0/fortio-linux_amd64-1.28.0.tgz \
  | sudo tar -C / -xvzpf -
 # or the debian package
-wget https://github.com/fortio/fortio/releases/download/v1.27.0/fortio_1.27.0_amd64.deb
-dpkg -i fortio_1.27.0_amd64.deb
+wget https://github.com/fortio/fortio/releases/download/v1.28.0/fortio_1.28.0_amd64.deb
+dpkg -i fortio_1.28.0_amd64.deb
 # or the rpm
-rpm -i https://github.com/fortio/fortio/releases/download/v1.27.0/fortio-1.27.0-1.x86_64.rpm
+rpm -i https://github.com/fortio/fortio/releases/download/v1.28.0/fortio-1.28.0-1.x86_64.rpm
 # and more, see assets in release page
 ```
 
@@ -66,7 +66,7 @@ On a MacOS you can also install Fortio using [Homebrew](https://brew.sh/):
 brew install fortio
 ```
 
-On Windows, download https://github.com/fortio/fortio/releases/download/v1.27.0/fortio_win_1.27.0.zip and extract `fortio.exe` to any location, then using the Windows Command Prompt:
+On Windows, download https://github.com/fortio/fortio/releases/download/v1.28.0/fortio_win_1.28.0.zip and extract `fortio.exe` to any location, then using the Windows Command Prompt:
 ```
 fortio.exe server
 ```
@@ -112,7 +112,7 @@ Full list of command line flags (`fortio help`):
 <details>
 <!-- use release/updateFlags.sh to update this section -->
 <pre>
-Φορτίο 1.27.0 usage:
+Φορτίο 1.28.0 usage:
 where command is one of: load (load testing), server (starts ui, http-echo,
  redirect, proxies, tcp-echo and grpc ping servers), tcp-echo (only the tcp-echo
  server), report (report only UI server), redirect (only the redirect server),
@@ -381,6 +381,13 @@ http://localhost:8080/fortio/
 14:11:05 I fortio_main.go:293> All fortio X.Y.Z unknown goM.m.p servers started!
 ```
 
+### Sample of the graphing UI
+
+With the 2 histograms - total and errors overlayed
+
+![Graphical result](https://user-images.githubusercontent.com/3664595/165001248-33e180d5-fd6b-4389-b73e-79a21e76d5b0.png)
+
+
 ### Change the port / binding address
 
 By default, Fortio's web/echo servers listen on port 8080 on all interfaces.
diff --git a/fgrpc/grpcrunner.go b/fgrpc/grpcrunner.go
index 5b6951f..79e217b 100644
--- a/fgrpc/grpcrunner.go
+++ b/fgrpc/grpcrunner.go
@@ -80,7 +80,7 @@ type GRPCRunnerResults struct {
 
 // Run exercises GRPC health check or ping at the target QPS.
 // To be set as the Function in RunnerOptions.
-func (grpcstate *GRPCRunnerResults) Run(t int) {
+func (grpcstate *GRPCRunnerResults) Run(t int) (bool, string) {
 	log.Debugf("Calling in %d", t)
 	var err error
 	var res interface{}
@@ -99,9 +99,13 @@ func (grpcstate *GRPCRunnerResults) Run(t int) {
 	if err != nil {
 		log.Warnf("Error making grpc call: %v", err)
 		grpcstate.RetCodes[Error]++
-	} else {
-		grpcstate.RetCodes[status.String()]++
+		return false, err.Error()
+	}
+	grpcstate.RetCodes[status.String()]++
+	if status == grpc_health_v1.HealthCheckResponse_SERVING {
+		return true, "SERVING"
 	}
+	return false, status.String()
 }
 
 // GRPCRunnerOptions includes the base RunnerOptions plus grpc specific
diff --git a/fhttp/httprunner.go b/fhttp/httprunner.go
index b29d0bb..bf83f4f 100644
--- a/fhttp/httprunner.go
+++ b/fhttp/httprunner.go
@@ -16,6 +16,7 @@ package fhttp
 
 import (
 	"fmt"
+	"net/http"
 	"os"
 	"runtime"
 	"runtime/pprof"
@@ -51,7 +52,7 @@ type HTTPRunnerResults struct {
 
 // Run tests http request fetching. Main call being run at the target QPS.
 // To be set as the Function in RunnerOptions.
-func (httpstate *HTTPRunnerResults) Run(t int) {
+func (httpstate *HTTPRunnerResults) Run(t int) (bool, string) {
 	log.Debugf("Calling in %d", t)
 	code, body, headerSize := httpstate.client.Fetch()
 	size := len(body)
@@ -63,6 +64,10 @@ func (httpstate *HTTPRunnerResults) Run(t int) {
 		httpstate.aborter.Abort()
 		log.Infof("Aborted run because of code %d - data %s", code, DebugSummary(body, 1024))
 	}
+	if code == http.StatusOK {
+		return true, "200"
+	}
+	return false, fmt.Sprint(code)
 }
 
 // HTTPRunnerOptions includes the base RunnerOptions plus http specific
diff --git a/periodic/periodic.go b/periodic/periodic.go
index 1f8fa59..4ab3021 100644
--- a/periodic/periodic.go
+++ b/periodic/periodic.go
@@ -52,7 +52,10 @@ var DefaultRunnerOptions = RunnerOptions{
 
 // Runnable are the function to run periodically.
 type Runnable interface {
-	Run(tid int)
+	// Run returns a boolean, true for normal/success, false otherwise.
+	// with details being an optional string that can be put in the access logs.
+	// Statistics are split into two sets.
+	Run(tid int) (status bool, details string)
 }
 
 // MakeRunners creates an array of NumThreads identical Runnable instances
@@ -159,13 +162,16 @@ type RunnerResults struct {
 	ActualDuration    time.Duration
 	NumThreads        int
 	Version           string
+	// DurationHistogram all the Run. If you want to exclude the error cases; subtract ErrorsDurationHistogram to each bucket.
 	DurationHistogram *stats.HistogramData
-	Exactly           int64 // Echo back the requested count
-	Jitter            bool
-	Uniform           bool
-	NoCatchUp         bool
-	RunID             int64 // Echo back the optional run id
-	AccessLoggerInfo  string
+	// ErrorsDurationHistogram is the durations of the error (Run returning false) cases.
+	ErrorsDurationHistogram *stats.HistogramData
+	Exactly                 int64 // Echo back the requested count
+	Jitter                  bool
+	Uniform                 bool
+	NoCatchUp               bool
+	RunID                   int64 // Echo back the optional run id
+	AccessLoggerInfo        string
 }
 
 // HasRunnerResult is the interface implictly implemented by HTTPRunnerResults
@@ -397,7 +403,7 @@ func (r *periodicRunner) runMaxQPSSetup(extra string) (requestedDuration string,
 // Run starts the runner.
 func (r *periodicRunner) Run() RunnerResults {
 	r.Stop.Lock()
-	runnerChan := r.Stop.StopChan // need a copy to not race with assignement to nil
+	runnerChan := r.Stop.StopChan // need a copy to not race with assignment to nil
 	r.Stop.Unlock()
 	useQPS := (r.QPS > 0)
 	// r.Exactly is > 0 if we use Exactly iterations instead of the duration.
@@ -427,19 +433,21 @@ func (r *periodicRunner) Run() RunnerResults {
 	start := time.Now()
 	// Histogram  and stats for Function duration - millisecond precision
 	functionDuration := stats.NewHistogram(r.Offset.Seconds(), r.Resolution)
+	errorsDuration := stats.NewHistogram(r.Offset.Seconds(), r.Resolution)
 	// Histogram and stats for Sleep time (negative offset to capture <0 sleep in their own bucket):
 	sleepTime := stats.NewHistogram(-0.001, 0.001)
 	if r.NumThreads <= 1 {
 		log.LogVf("Running single threaded")
-		runOne(0, runnerChan, functionDuration, sleepTime, numCalls+leftOver, start, r)
+		runOne(0, runnerChan, functionDuration, errorsDuration, sleepTime, numCalls+leftOver, start, r)
 	} else {
 		var wg sync.WaitGroup
-		var fDs []*stats.Histogram
-		var sDs []*stats.Histogram
+		var fDs, eDs, sDs []*stats.Histogram
 		for t := 0; t < r.NumThreads; t++ {
 			durP := functionDuration.Clone()
+			errP := errorsDuration.Clone()
 			sleepP := sleepTime.Clone()
 			fDs = append(fDs, durP)
+			eDs = append(eDs, errP)
 			sDs = append(sDs, sleepP)
 			wg.Add(1)
 			thisNumCalls := numCalls
@@ -447,14 +455,15 @@ func (r *periodicRunner) Run() RunnerResults {
 				// The first thread gets to do the additional work
 				thisNumCalls += leftOver
 			}
-			go func(t int, durP *stats.Histogram, sleepP *stats.Histogram) {
-				runOne(t, runnerChan, durP, sleepP, thisNumCalls, start, r)
+			go func(t int, durP, errP, sleepP *stats.Histogram) {
+				runOne(t, runnerChan, durP, errP, sleepP, thisNumCalls, start, r)
 				wg.Done()
-			}(t, durP, sleepP)
+			}(t, durP, errP, sleepP)
 		}
 		wg.Wait()
 		for t := 0; t < r.NumThreads; t++ {
 			functionDuration.Transfer(fDs[t])
+			errorsDuration.Transfer(eDs[t])
 			sleepTime.Transfer(sDs[t])
 		}
 	}
@@ -490,15 +499,18 @@ func (r *periodicRunner) Run() RunnerResults {
 	result := RunnerResults{
 		r.RunType, r.Labels, start, requestedQPS, requestedDuration,
 		actualQPS, elapsed, r.NumThreads, version.Short(), functionDuration.Export().CalcPercentiles(r.Percentiles),
+		errorsDuration.Export().CalcPercentiles(r.Percentiles),
 		r.Exactly, r.Jitter, r.Uniform, r.NoCatchUp, r.RunID, loggerInfo,
 	}
 	if log.Log(log.Warning) {
 		result.DurationHistogram.Print(r.Out, "Aggregated Function Time")
+		result.ErrorsDurationHistogram.Print(r.Out, "Error cases")
 	} else {
 		functionDuration.Counter.Print(r.Out, "Aggregated Function Time")
 		for _, p := range result.DurationHistogram.Percentiles {
 			_, _ = fmt.Fprintf(r.Out, "# target %g%% %.6g\n", p.Percentile, p.Value)
 		}
+		errorsDuration.Counter.Print(r.Out, "Error cases")
 	}
 	select {
 	case <-runnerChan: // nothing
@@ -517,7 +529,7 @@ const (
 	// AccessJSON for json format of access log: {"latency":%f,"timestamp":%d,"thread":%d}.
 	AccessJSON AccessLoggerType = iota
 	// AccessInflux of influx format of access log.
-	// https://docs.influxdata.com/influxdb/v2.1/reference/syntax/line-protocol/
+	// https://docs.influxdata.com/influxdb/v2.2/reference/syntax/line-protocol/
 	AccessInflux
 )
 
@@ -538,7 +550,7 @@ type fileAccessLogger struct {
 // AccessLogger defines an interface to report a single request.
 type AccessLogger interface {
 	// Report logs a single request to a file.
-	Report(thread int, time int64, latency float64)
+	Report(thread int, time int64, latency float64, status bool, details string)
 	Info() string
 }
 
@@ -584,14 +596,15 @@ func NewFileAccessLoggerByType(filePath string, accessType AccessLoggerType) (Ac
 }
 
 // Report logs a single request to a file.
-func (a *fileAccessLogger) Report(thread int, time int64, latency float64) {
+func (a *fileAccessLogger) Report(thread int, time int64, latency float64, status bool, details string) {
 	a.mu.Lock()
 	switch a.format {
 	case AccessInflux:
-		// https://docs.influxdata.com/influxdb/v2.1/reference/syntax/line-protocol/
-		fmt.Fprintf(a.file, "latency,thread=%d value=%f %d\n", thread, latency, time)
+		// https://docs.influxdata.com/influxdb/v2.2/reference/syntax/line-protocol/
+		fmt.Fprintf(a.file, "latency,thread=%d,ok=%t value=%f,details=%q %d\n", thread, status, latency, details, time)
 	case AccessJSON:
-		fmt.Fprintf(a.file, "{\"latency\":%f,\"timestamp\":%d,\"thread\":%d}\n", latency, time, thread)
+		fmt.Fprintf(a.file, "{\"latency\":%f,\"timestamp\":%d,\"thread\":%d,\"ok\":%t,\"details\":%q}\n",
+			latency, time, thread, status, details)
 	}
 	a.mu.Unlock()
 }
@@ -602,9 +615,10 @@ func (a *fileAccessLogger) Info() string {
 }
 
 // runOne runs in 1 go routine (or main one when -c 1 == single threaded mode).
-// nolint: gocognit // we should try to simplify it though.
-func runOne(id int, runnerChan chan struct{},
-	funcTimes *stats.Histogram, sleepTimes *stats.Histogram, numCalls int64, start time.Time, r *periodicRunner) {
+// nolint: gocognit, gocyclo // we should try to simplify it though.
+func runOne(id int, runnerChan chan struct{}, funcTimes, errTimes, sleepTimes *stats.Histogram,
+	numCalls int64, start time.Time, r *periodicRunner,
+) {
 	var i int64
 	endTime := start.Add(r.Duration)
 	tIDStr := fmt.Sprintf("T%03d", id)
@@ -645,12 +659,15 @@ MainLoop:
 				break
 			}
 		}
-		f.Run(id)
+		status, details := f.Run(id)
 		latency := time.Since(fStart).Seconds()
 		if r.AccessLogger != nil {
-			r.AccessLogger.Report(id, fStart.UnixNano(), latency)
+			r.AccessLogger.Report(id, fStart.UnixNano(), latency, status, details)
 		}
 		funcTimes.Record(latency)
+		if !status {
+			errTimes.Record(latency)
+		}
 		// if using QPS / pre calc expected call # mode:
 		if useQPS { // nolint: nestif
 			for {
diff --git a/stats/stats.go b/stats/stats.go
index bb89914..2a24caf 100644
--- a/stats/stats.go
+++ b/stats/stats.go
@@ -61,11 +61,17 @@ func (c *Counter) RecordN(v float64, n int) {
 
 // Avg returns the average.
 func (c *Counter) Avg() float64 {
+	if c.Count == 0 {
+		return 0.
+	}
 	return c.Sum / float64(c.Count)
 }
 
 // StdDev returns the standard deviation.
 func (c *Counter) StdDev() float64 {
+	if c.Count == 0 {
+		return 0.
+	}
 	fC := float64(c.Count)
 	sigma := (c.sumOfSquares - c.Sum*c.Sum/fC) / fC
 	// should never happen but it does
diff --git a/tcprunner/tcprunner.go b/tcprunner/tcprunner.go
index 4e81b44..8fb5791 100644
--- a/tcprunner/tcprunner.go
+++ b/tcprunner/tcprunner.go
@@ -47,14 +47,16 @@ type RunnerResults struct {
 
 // Run tests tcp request fetching. Main call being run at the target QPS.
 // To be set as the Function in RunnerOptions.
-func (tcpstate *RunnerResults) Run(t int) {
+func (tcpstate *RunnerResults) Run(t int) (bool, string) {
 	log.Debugf("Calling in %d", t)
 	_, err := tcpstate.client.Fetch()
 	if err != nil {
-		tcpstate.RetCodes[err.Error()]++
-	} else {
-		tcpstate.RetCodes[TCPStatusOK]++
+		errStr := err.Error()
+		tcpstate.RetCodes[errStr]++
+		return false, errStr
 	}
+	tcpstate.RetCodes[TCPStatusOK]++
+	return true, TCPStatusOK
 }
 
 // TCPOptions are options to the TCPClient.
diff --git a/udprunner/udprunner.go b/udprunner/udprunner.go
index fb0fec7..d0f5808 100644
--- a/udprunner/udprunner.go
+++ b/udprunner/udprunner.go
@@ -50,14 +50,16 @@ type RunnerResults struct {
 
 // Run tests udp request fetching. Main call being run at the target QPS.
 // To be set as the Function in RunnerOptions.
-func (udpstate *RunnerResults) Run(t int) {
+func (udpstate *RunnerResults) Run(t int) (bool, string) {
 	log.Debugf("Calling in %d", t)
 	_, err := udpstate.client.Fetch()
 	if err != nil {
-		udpstate.RetCodes[err.Error()]++
-	} else {
-		udpstate.RetCodes[UDPStatusOK]++
+		errStr := err.Error()
+		udpstate.RetCodes[errStr]++
+		return false, errStr
 	}
+	udpstate.RetCodes[UDPStatusOK]++
+	return true, UDPStatusOK
 }
 
 // UDPOptions are options to the UDPClient.
diff --git a/ui/static/js/fortio_chart.js b/ui/static/js/fortio_chart.js
index 7ec89b1..730c05e 100644
--- a/ui/static/js/fortio_chart.js
+++ b/ui/static/js/fortio_chart.js
@@ -82,7 +82,7 @@ function pad (n) {
 function formatDate (dStr) {
   const d = new Date(dStr)
   return d.getFullYear() + '-' + pad(d.getMonth() + 1) + '-' + pad(d.getDate()) + ' ' +
-        pad(d.getHours()) + ':' + pad(d.getMinutes()) + ':' + pad(d.getSeconds())
+    pad(d.getHours()) + ':' + pad(d.getMinutes()) + ':' + pad(d.getSeconds())
 }
 
 function makeTitle (res) {
@@ -108,23 +108,32 @@ function makeTitle (res) {
     }
   }
   percStr += ', max ' + myRound(1000.0 * res.DurationHistogram.Max, 3) + ' ms'
-  let statusOk = res.RetCodes[200]
-  if (!statusOk) { // grpc or tcp results
-    statusOk = res.RetCodes.SERVING || res.RetCodes.OK
-  }
   const total = res.DurationHistogram.Count
   let errStr = 'no error'
-  if (statusOk !== total) {
-    if (statusOk) {
-      errStr = myRound(100.0 * (total - statusOk) / total, 2) + '% errors'
-    } else {
-      errStr = '100% errors!'
+  if (res.ErrorsDurationHistogram != null) {
+    // Newer simpler calculation when we have the ErrorsDurationHistogram:
+    const statusNotOk = res.ErrorsDurationHistogram.Count
+    if (statusNotOk !== 0) {
+      errStr = myRound(100.0 * statusNotOk / total, 2) + '% errors'
+    }
+  } else {
+    // Old calculation (for older saved data)
+    let statusOk = res.RetCodes[200]
+    if (!statusOk) { // grpc or tcp results
+      statusOk = res.RetCodes.SERVING || res.RetCodes.OK
+    }
+    if (statusOk !== total) {
+      if (statusOk) {
+        errStr = myRound(100.0 * (total - statusOk) / total, 2) + '% errors'
+      } else {
+        errStr = '100% errors!'
+      }
     }
   }
   title.push('Response time histogram at ' + res.RequestedQPS + ' target qps (' +
-        myRound(res.ActualQPS, 1) + ' actual) ' + res.NumThreads + ' connections for ' +
-        res.RequestedDuration + ' (actual time ' + myRound(res.ActualDuration / 1e9, 1) + 's), jitter: ' +
-        res.Jitter + ', uniform: ' + res.Uniform + ', ' + errStr)
+    myRound(res.ActualQPS, 1) + ' actual) ' + res.NumThreads + ' connections for ' +
+    res.RequestedDuration + ' (actual time ' + myRound(res.ActualDuration / 1e9, 1) + 's), jitter: ' +
+    res.Jitter + ', uniform: ' + res.Uniform + ', ' + errStr)
   title.push(percStr)
   return title
 }
@@ -134,63 +143,94 @@ function fortioResultToJsChartData (res) {
     x: 0.0,
     y: 0.0
   }]
-  const len = res.DurationHistogram.Data.length
-  let prevX = 0.0
-  let prevY = 0.0
-  for (let i = 0; i < len; i++) {
-    const it = res.DurationHistogram.Data[i]
-    let x = myRound(1000.0 * it.Start)
-    if (i === 0) {
+  const dataH = []
+  const dataE = []
+  if (res.DurationHistogram.Count > 0) {
+    const len = res.DurationHistogram.Data.length
+    let prevX = 0.0
+    let prevY = 0.0
+    for (let i = 0; i < len; i++) {
+      const it = res.DurationHistogram.Data[i]
+      let x = myRound(1000.0 * it.Start)
+      if (i === 0) {
       // Extra point, 1/N at min itself
-      dataP.push({
-        x: x,
-        y: myRound(100.0 / res.DurationHistogram.Count, 3)
-      })
-    } else {
-      if (prevX !== x) {
         dataP.push({
-          x: x,
-          y: prevY
+          x,
+          y: myRound(100.0 / res.DurationHistogram.Count, 3)
         })
+      } else {
+        if (prevX !== x) {
+          dataP.push({
+            x,
+            y: prevY
+          })
+        }
       }
+      x = myRound(1000.0 * it.End)
+      const y = myRound(it.Percent, 3)
+      dataP.push({
+        x,
+        y
+      })
+      prevX = x
+      prevY = y
     }
-    x = myRound(1000.0 * it.End)
-    const y = myRound(it.Percent, 3)
-    dataP.push({
-      x: x,
-      y: y
-    })
-    prevX = x
-    prevY = y
-  }
-  const dataH = []
-  let prev = 1000.0 * res.DurationHistogram.Data[0].Start
-  for (let i = 0; i < len; i++) {
-    const it = res.DurationHistogram.Data[i]
-    const startX = 1000.0 * it.Start
-    const endX = 1000.0 * it.End
-    if (startX !== prev) {
+    let prev = 1000.0 * res.DurationHistogram.Data[0].Start
+    for (let i = 0; i < len; i++) {
+      const it = res.DurationHistogram.Data[i]
+      const startX = 1000.0 * it.Start
+      const endX = 1000.0 * it.End
+      if (startX !== prev) {
+        dataH.push({
+          x: myRound(prev),
+          y: 0
+        }, {
+          x: myRound(startX),
+          y: 0
+        })
+      }
       dataH.push({
-        x: myRound(prev),
-        y: 0
+        x: myRound(startX),
+        y: it.Count
       }, {
+        x: myRound(endX),
+        y: it.Count
+      })
+      prev = endX
+    }
+  }
+  if (res.ErrorsDurationHistogram != null && res.ErrorsDurationHistogram.Count > 0) {
+    // TODO: make a function, same as above with dataH->dataE
+    let prev = 1000.0 * res.ErrorsDurationHistogram.Data[0].Start
+    const len = res.ErrorsDurationHistogram.Data.length
+    for (let i = 0; i < len; i++) {
+      const it = res.ErrorsDurationHistogram.Data[i]
+      const startX = 1000.0 * it.Start
+      const endX = 1000.0 * it.End
+      if (startX !== prev) {
+        dataE.push({
+          x: myRound(prev),
+          y: 0
+        }, {
+          x: myRound(startX),
+          y: 0
+        })
+      }
+      dataE.push({
         x: myRound(startX),
-        y: 0
+        y: it.Count
+      }, {
+        x: myRound(endX),
+        y: it.Count
       })
+      prev = endX
     }
-    dataH.push({
-      x: myRound(startX),
-      y: it.Count
-    }, {
-      x: myRound(endX),
-      y: it.Count
-    })
-    prev = endX
   }
   return {
     title: makeTitle(res),
-    dataP: dataP,
-    dataH: dataH
+    dataP,
+    dataH,
+    dataE
   }
 }
 
@@ -321,6 +361,16 @@ function makeChart (data) {
           borderColor: 'rgba(134, 87, 167, 1)',
           cubicInterpolationMode: 'monotone'
         },
+        {
+          label: 'Error Histogram',
+          data: data.dataE,
+          yAxisID: 'H',
+          pointStyle: 'rect',
+          radius: 1,
+          borderColor: 'rgba(179, 42, 18, .8)',
+          backgroundColor: 'rgba(179, 42, 18, .65)',
+          lineTension: 0
+        },
         {
           label: 'Histogram: Count',
           data: data.dataH,
@@ -365,7 +415,8 @@ function makeChart (data) {
     // TODO may need updateChart() if we persist settings even the first time
   } else {
     chart.data.datasets[0].data = data.dataP
-    chart.data.datasets[1].data = data.dataH
+    chart.data.datasets[1].data = data.dataE
+    chart.data.datasets[2].data = data.dataH
     chart.options.title.text = data.title
     updateChart(chart)
   }


Test patch:
diff --git a/Webtest.sh b/Webtest.sh
index 2caaa32..43218b6 100755
--- a/Webtest.sh
+++ b/Webtest.sh
@@ -14,7 +14,9 @@
 # limitations under the License.
 set -x
 # Check we can build the image
-make docker-internal TAG=webtest || exit 1
+NATIVE_PLATFORM=$(docker buildx --builder default inspect | tail -1 | sed -e "s/Platforms: //" -e "s/,//g" | awk '{print $1}')
+echo "Building for $NATIVE_PLATFORM"
+make docker-internal TAG=webtest BUILDX_PLATFORMS="$NATIVE_PLATFORM" || exit 1
 FORTIO_UI_PREFIX=/newprefix/ # test the non default prefix (not /fortio/)
 FILE_LIMIT=25 # must be low to detect leaks, go 1.14 seems to need more than go1.8 (!)
 LOGLEVEL=info # change to debug to debug
diff --git a/fhttp/http_forwarder_test.go b/fhttp/http_forwarder_test.go
index 484274f..19fe034 100644
--- a/fhttp/http_forwarder_test.go
+++ b/fhttp/http_forwarder_test.go
@@ -19,14 +19,8 @@ import (
 	"fmt"
 	"net/http"
 	"testing"
-
-	"fortio.org/fortio/log"
 )
 
-func init() {
-	log.SetLogLevel(log.Debug)
-}
-
 func TestMultiProxy(t *testing.T) {
 	_, debugAddr := ServeTCP("0", "/debug")
 	urlBase := fmt.Sprintf("localhost:%d/", debugAddr.Port)
diff --git a/fhttp/http_test.go b/fhttp/http_test.go
index 2833355..030563c 100644
--- a/fhttp/http_test.go
+++ b/fhttp/http_test.go
@@ -36,7 +36,6 @@ import (
 var uuids map[string]bool
 
 func init() {
-	log.SetLogLevel(log.Debug)
 	uuids = map[string]bool{}
 }
 
diff --git a/fhttp/httprunner_test.go b/fhttp/httprunner_test.go
index bf14734..677d507 100644
--- a/fhttp/httprunner_test.go
+++ b/fhttp/httprunner_test.go
@@ -16,10 +16,13 @@
 package fhttp
 
 import (
+	"bufio"
 	"bytes"
 	"compress/gzip"
 	"fmt"
 	"net/http"
+	"os"
+	"path"
 	"runtime"
 	"strings"
 	"testing"
@@ -80,7 +83,8 @@ func testHTTPNotLeaking(t *testing.T, opts *HTTPRunnerOptions) {
 	t.Logf("Number go routine before test %d", ngBefore1)
 	mux, addr := DynamicHTTPServer(false)
 	mux.HandleFunc("/echo100", EchoHandler)
-	url := fmt.Sprintf("http://localhost:%d/echo100", addr.Port)
+	// Avoid using localhost which can timeout with stdclient (thought this might fail on ipv6 only machines?)
+	url := fmt.Sprintf("http://127.0.0.1:%d/echo100", addr.Port)
 	numCalls := 100
 	opts.NumThreads = numCalls / 2 // make 2 calls per thread
 	opts.Exactly = int64(numCalls)
@@ -247,6 +251,84 @@ func gUnzipData(t *testing.T, data []byte) (resData []byte) {
 	return
 }
 
+// nolint: gocognit
+func TestAccessLog(t *testing.T) {
+	mux, addr := DynamicHTTPServer(false)
+	mux.HandleFunc("/echo-for-alog/", EchoHandler)
+	URL := fmt.Sprintf("http://localhost:%d/echo-for-alog/?status=555:50", addr.Port)
+	opts := HTTPRunnerOptions{}
+	opts.Init(URL)
+	opts.QPS = 10
+	numReq := int64(50) // can't do too many without running out of fds on mac
+	opts.Exactly = numReq
+	opts.NumThreads = 5
+	for _, format := range []string{"json", "influx"} {
+		dir := t.TempDir()
+		fname := path.Join(dir, "access.log")
+		err := opts.AddAccessLogger(fname, format)
+		if err != nil {
+			t.Errorf("unexpected error for log file %q %s: %v", fname, format, err)
+		}
+		res, err := RunHTTPTest(&opts)
+		if err != nil {
+			t.Fatal(err)
+		}
+		totalReq := res.DurationHistogram.Count
+		if totalReq != numReq {
+			t.Errorf("Mismatch between requests %d and expected %d", totalReq, numReq)
+		}
+		httpOk := res.RetCodes[http.StatusOK]
+		http555 := res.RetCodes[555]
+		if httpOk <= 1 || httpOk >= numReq-1 {
+			t.Errorf("Unexpected ok count %d should be ~ 50%% of %d", httpOk, numReq)
+		}
+		if http555 <= 1 || http555 >= numReq-1 {
+			t.Errorf("Unexpected 555 count %d should be ~ 50%% of %d", http555, numReq)
+		}
+		if totalReq != httpOk+http555 {
+			t.Errorf("Mismatch between requests %d and ok+555 %v", totalReq, res.RetCodes)
+		}
+		file, _ := os.Open(fname)
+		scanner := bufio.NewScanner(file)
+		lineCount := 0
+		linesOk := 0
+		linesNotOk := 0
+		lines200 := 0
+		lines555 := 0
+		for scanner.Scan() {
+			line := scanner.Text()
+			if strings.Contains(line, "true") {
+				linesOk++
+			}
+			if strings.Contains(line, "false") {
+				linesNotOk++
+			}
+			if strings.Contains(line, "\"200\"") {
+				lines200++
+			}
+			if strings.Contains(line, "\"555\"") {
+				lines555++
+			}
+			lineCount++
+		}
+		if lineCount != int(numReq) {
+			t.Errorf("unexpected number of lines in access log %s: %d", format, lineCount)
+		}
+		if linesOk != int(httpOk) {
+			t.Errorf("unexpected number of lines in access log %s: with ok: %d instead of %d", format, linesOk, httpOk)
+		}
+		if lines200 != int(httpOk) {
+			t.Errorf("unexpected number of lines in access log %s: with 200: %d instead of %d", format, lines200, httpOk)
+		}
+		if linesNotOk != int(http555) {
+			t.Errorf("unexpected number of lines in access log %s: with not ok: %d instead of %d", format, linesNotOk, http555)
+		}
+		if lines555 != int(http555) {
+			t.Errorf("unexpected number of lines in access log %s: with 555: %d instead of %d", format, lines555, http555)
+		}
+	}
+}
+
 // need to be the last test as it installs Serve() which would make
 // the error test for / url above fail:
 
diff --git a/periodic/periodic_test.go b/periodic/periodic_test.go
index b5a350f..ab85f06 100644
--- a/periodic/periodic_test.go
+++ b/periodic/periodic_test.go
@@ -15,8 +15,10 @@
 package periodic
 
 import (
+	"bufio"
 	"math"
 	"os"
+	"path"
 	"strings"
 	"sync"
 	"testing"
@@ -27,7 +29,8 @@ import (
 
 type Noop struct{}
 
-func (n *Noop) Run(t int) {
+func (n *Noop) Run(t int) (bool, string) {
+	return true, ""
 }
 
 // used for when we don't actually run periodic test/want to initialize
@@ -75,11 +78,13 @@ type TestCount struct {
 	lock  *sync.Mutex
 }
 
-func (c *TestCount) Run(i int) {
+func (c *TestCount) Run(i int) (bool, string) {
 	c.lock.Lock()
 	(*c.count)++
+	status := (*c.count)%2 == 0
 	c.lock.Unlock()
 	time.Sleep(100 * time.Millisecond)
+	return status, ""
 }
 
 func TestStart(t *testing.T) {
@@ -227,12 +232,16 @@ func TestExactlyMaxQps(t *testing.T) {
 type testAccessLogger struct {
 	sync.Mutex
 	reports int64
+	success int64
 }
 
-func (t *testAccessLogger) Report(thread int, time int64, latency float64) {
+func (t *testAccessLogger) Report(thread int, time int64, latency float64, status bool, details string) {
 	t.Lock()
 	defer t.Unlock()
 	t.reports++
+	if status {
+		t.success++
+	}
 }
 
 func (t *testAccessLogger) Info() string {
@@ -268,9 +277,77 @@ func TestAccessLogs(t *testing.T) {
 	if count != expected {
 		t.Errorf("Access logs executed unexpected number of times %d instead %d", count, expected)
 	}
+	if logger.success != expected/2 {
+		t.Errorf("Access logs status success unexpected number of times %d instead %d", logger.success, expected/2)
+	}
 	r.Options().ReleaseRunners()
 }
 
+func TestAccessLogFile(t *testing.T) {
+	var count int64
+	var lock sync.Mutex
+
+	c := TestCount{&count, &lock}
+	expected := int64(10)
+	o := RunnerOptions{
+		QPS:        -1, // max qps
+		NumThreads: 4,
+		Exactly:    expected,
+	}
+
+	for _, format := range []string{"json", "influx"} {
+		dir := t.TempDir()
+		fname := path.Join(dir, "access.log")
+		err := o.AddAccessLogger(fname, format)
+		r := NewPeriodicRunner(&o)
+		r.Options().MakeRunners(&c)
+		count = 0
+		if err != nil {
+			t.Errorf("unexpected error for log file %q %s: %v", fname, format, err)
+		}
+		res := r.Run()
+		totalReq := res.DurationHistogram.Count
+		if totalReq != expected {
+			t.Errorf("Mismatch between requests %d and expected %d", totalReq, expected)
+		}
+		if count != expected {
+			t.Errorf("Mismatch between count %d and expected %d", count, expected)
+		}
+		numErr := res.ErrorsDurationHistogram.Count
+		if numErr <= 1 || numErr >= expected-1 {
+			t.Errorf("Unexpected non ok count %d should be ~ 50%% of %d", numErr, expected)
+		}
+		numOk := res.DurationHistogram.Count - numErr
+		if numOk <= 1 || numOk >= expected-1 {
+			t.Errorf("Unexpected ok count %d should be ~ 50%% of %d", numOk, expected)
+		}
+		file, _ := os.Open(fname)
+		scanner := bufio.NewScanner(file)
+		lineCount := 0
+		linesOk := 0
+		linesNotOk := 0
+		for scanner.Scan() {
+			line := scanner.Text()
+			if strings.Contains(line, "true") {
+				linesOk++
+			}
+			if strings.Contains(line, "false") {
+				linesNotOk++
+			}
+			lineCount++
+		}
+		if lineCount != int(expected) {
+			t.Errorf("unexpected number of lines in access log %s: %d", format, lineCount)
+		}
+		if linesOk != int(numOk) {
+			t.Errorf("unexpected number of lines in access log %s: with ok: %d instead of %d", format, linesOk, numOk)
+		}
+		if linesNotOk != int(numErr) {
+			t.Errorf("unexpected number of lines in access log %s: with not ok: %d instead of %d", format, linesNotOk, numErr)
+		}
+	}
+}
+
 func TestUniformAndNoCatchUp(t *testing.T) {
 	var count int64
 	var lock sync.Mutex
diff --git a/stats/stats_test.go b/stats/stats_test.go
index 41269e5..5cb591e 100644
--- a/stats/stats_test.go
+++ b/stats/stats_test.go
@@ -34,7 +34,7 @@ func TestCounter(t *testing.T) {
 	var b bytes.Buffer
 	w := bufio.NewWriter(&b)
 	c.Counter.Print(w, "test1c")
-	expected := "test1c : count 0 avg NaN +/- NaN min 0 max 0 sum 0\n"
+	expected := "test1c : count 0 avg 0 +/- 0 min 0 max 0 sum 0\n"
 	c.Print(w, "test1h", []float64{50.0})
 	expected += "test1h : no data\n"
 	*log.LogFileAndLine = false
@@ -118,9 +118,9 @@ func TestTransferCounter(t *testing.T) {
 	expected := `c1 before merge : count 2 avg 15 +/- 5 min 10 max 20 sum 30
 c2 before merge : count 2 avg 85 +/- 5 min 80 max 90 sum 170
 mergedC1C2 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
-c2 after merge : count 0 avg NaN +/- NaN min 0 max 0 sum 0
+c2 after merge : count 0 avg 0 +/- 0 min 0 max 0 sum 0
 mergedC2C1 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
-c1 should now be empty : count 0 avg NaN +/- NaN min 0 max 0 sum 0
+c1 should now be empty : count 0 avg 0 +/- 0 min 0 max 0 sum 0
 c3 after merge - 1 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
 c3 after merge - 2 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
 `