Save the async result file even on init error (like invalid host/targ…

…et) (#797)

* Fix #796 - save the async result file even on init error

* handle ui look of error json

* fix panic when runner options are minimal like in tests

* fix exception mismatch on linux/circle ci

* fix logic for init error and being done with start chan

* use newer log/scli to see goroutine IDs in logs to troubleshoot concurrency

* move codecov to github action so it actually reports now

* lowering load in rapi udp/tcp/grpc tests

* added more info in logs and (kinda) fixed concurrency issue with start

* ./release/bumpRelease.sh  1.57.4

.circleci/config.yml

@@ -32,19 +32,19 @@ jobs:
       - checkout
       # If ran with default we get random errors because OOM killer kills some linters
       - run: make local-lint DEBUG_LINTERS="--concurrency=2"
-  codecov:
-    <<: *defaultEnv
-    steps:
-      - checkout
-      - run: make coverage
-    # The resource_class feature allows configuring CPU and RAM resources for each job. Different resource classes are available for different executors. https://circleci.com/docs/2.0/configuration-reference/#resourceclass
-    resource_class: large
+  # codecov:
+  #   <<: *defaultEnv
+  #   steps:
+  #     - checkout
+  #     - run: make coverage
+  #   # The resource_class feature allows configuring CPU and RAM resources for each job. Different resource classes are available for different executors. https://circleci.com/docs/2.0/configuration-reference/#resourceclass
+  #   resource_class: large
 
 workflows:
   version: 2
   all:
     jobs:
       - unit-tests
       - release-tests
-      - codecov
+#      - codecov
       - linters

.circleci/coverage.sh

@@ -2,8 +2,10 @@
 
 set -e
 echo "" > coverage.txt
+rm -f profile.out
 
 for d in $(go list ./... | grep -v vendor); do
+    echo "### Working on package coverage $d"
     go test -coverprofile=profile.out -covermode=atomic $d
     if [ -f profile.out ]; then
         cat profile.out >> coverage.txt

.github/workflows/codecov.yml

@@ -0,0 +1,25 @@
+name: Test Coverage
+
+on:
+  push:
+    branches: [ master ]
+  pull_request:
+    # The branches below must be a subset of the branches above
+    branches: [ master ]
+
+jobs:
+  build:
+    runs-on: ubuntu-latest
+    steps:
+      - uses: actions/checkout@c85c95e3d7251135ab7dc9ce3241c5835cc595a9 # pin@v3
+        with:
+          fetch-depth: 2
+      - name: Set up Go
+        uses: actions/setup-go@fac708d6674e30b6ba41289acaab6d4b75aa0753 # pin@v4
+        with:
+          go-version: '1.20'
+          check-latest: true
+      - name: Run coverage
+        run: make coverage
+      - name: Upload coverage to Codecov
+        uses: codecov/codecov-action@eaaf4bedf32dbdc6b720b63067d99c4d77d6047d # pin@v3

Makefile

@@ -86,7 +86,7 @@ webtest: release-test
 
 coverage: dependencies
 	./.circleci/coverage.sh
-	curl -s https://codecov.io/bash | bash
+#	curl -s https://codecov.io/bash | bash
 
 # Short cut for pulling/updating to latest of the current branch
 pull:

README.md

@@ -1,4 +1,4 @@
-<!-- 1.57.3 -->
+<!-- 1.57.4 -->
 # Fortio
 
 [![Awesome Go](https://fortio.org/mentioned-badge.svg)](https://github.com/avelino/awesome-go#networking)
@@ -60,13 +60,13 @@ You can install from source:
 The [releases](https://github.com/fortio/fortio/releases) page has binaries for many OS/architecture combinations (see assets):
 
 ```shell
-curl -L https://github.com/fortio/fortio/releases/download/v1.57.3/fortio-linux_amd64-1.57.3.tgz \
+curl -L https://github.com/fortio/fortio/releases/download/v1.57.4/fortio-linux_amd64-1.57.4.tgz \
  | sudo tar -C / -xvzpf -
 # or the debian package
-wget https://github.com/fortio/fortio/releases/download/v1.57.3/fortio_1.57.3_amd64.deb
-dpkg -i fortio_1.57.3_amd64.deb
+wget https://github.com/fortio/fortio/releases/download/v1.57.4/fortio_1.57.4_amd64.deb
+dpkg -i fortio_1.57.4_amd64.deb
 # or the rpm
-rpm -i https://github.com/fortio/fortio/releases/download/v1.57.3/fortio-1.57.3-1.x86_64.rpm
+rpm -i https://github.com/fortio/fortio/releases/download/v1.57.4/fortio-1.57.4-1.x86_64.rpm
 # and more, see assets in release page
 ```
 
@@ -76,7 +76,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.57.3/fortio_win_1.57.3.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.57.4/fortio_win_1.57.4.zip and extract `fortio.exe` to any location, then using the Windows Command Prompt:
 ```
 fortio.exe server
 ```
@@ -128,7 +128,7 @@ Full list of command line flags (`fortio help`):
 <!-- use release/updateFlags.sh to update this section -->
 <pre>
 <!-- USAGE_START -->
-Φορτίο 1.57.3 usage:
+Φορτίο 1.57.4 usage:
         fortio command [flags] target
 where command is one of: load (load testing), server (starts ui, rest api,
  http-echo, redirect, proxies, tcp-echo, udp-echo and grpc ping servers),
@@ -256,6 +256,9 @@ URL and hostname
 disable (default true)
   -logger-force-color
         Force color output even if stderr isn't a terminal
+  -logger-goroutine
+        GoroutineID emitted in JSON/color logs, use -logger-goroutine=false to disable
+(default true)
   -logger-json
         Log in JSON format, use -logger-json=false to disable (default true)
   -logger-no-color

fhttp/httprunner.go

@@ -23,7 +23,9 @@ import (
 	"sort"
 	"strconv"
 	"sync"
+	"time"
 
+	"fortio.org/fortio/jrpc"
 	"fortio.org/fortio/periodic"
 	"fortio.org/fortio/stats"
 	"fortio.org/log"
@@ -83,6 +85,25 @@ type HTTPRunnerOptions struct {
 	AbortOn int
 }
 
+func NewErrorResult(o *HTTPRunnerOptions, message string, err error) *HTTPRunnerResults {
+	log.LogVf("New error result %s: %v", message, err)
+	empty := stats.NewHistogram(0, periodic.DefaultRunnerOptions.Resolution)
+	empty.Record(0.)
+	empty.Record(0.001) // 2 points to generate a big red block when visualized in browse UI.
+	return &HTTPRunnerResults{
+		HTTPOptions: o.HTTPOptions,
+		RunnerResults: periodic.RunnerResults{
+			StartTime:               time.Now(),
+			RunType:                 o.RunType,
+			RunID:                   o.RunID,
+			ID:                      o.RunnerOptions.ID,
+			ServerReply:             *jrpc.NewErrorReply(message, err),
+			DurationHistogram:       empty.Export(),
+			ErrorsDurationHistogram: empty.Export(),
+		},
+	}
+}
+
 // RunHTTPTest runs an http test and returns the aggregated stats.
 //
 //nolint:funlen, gocognit, gocyclo, maintidx
@@ -112,14 +133,15 @@ func RunHTTPTest(o *HTTPRunnerOptions) (*HTTPRunnerResults, error) {
 	o.HTTPOptions.UniqueID = o.RunnerOptions.RunID
 	o.HTTPOptions.Init(o.URL)
 	out := r.Options().Out // Important as the default value is set from nil to stdout inside NewPeriodicRunner
+	aborter := r.Options().Stop
 	total := HTTPRunnerResults{
 		HTTPOptions: o.HTTPOptions,
 		RetCodes:    make(map[int]int64),
 		IPCountMap:  make(map[string]int),
 		sizes:       stats.NewHistogram(0, 100),
 		headerSizes: stats.NewHistogram(0, 5),
 		AbortOn:     o.AbortOn,
-		aborter:     r.Options().Stop,
+		aborter:     aborter,
 	}
 	httpstate := make([]HTTPRunnerResults, numThreads)
 	// First build all the clients sequentially. This ensures we do not have data races when
@@ -134,12 +156,15 @@ func RunHTTPTest(o *HTTPRunnerOptions) (*HTTPRunnerResults, error) {
 		httpstate[i].client, err = NewClient(&o.HTTPOptions)
 		// nil check on interface doesn't work
 		if err != nil {
-			return nil, err
+			aborter.RecordStart() // virtual/fake start so when we use the start chan later to wait it doesn't hang
+			return NewErrorResult(o, "init error", err), err
 		}
 		if o.SequentialWarmup && o.Exactly <= 0 {
 			code, dataLen, headerSize := httpstate[i].client.StreamFetch(ctx)
 			if !o.AllowInitialErrors && !codeIsOK(code) {
-				return nil, fmt.Errorf("error %d for %s (%d body bytes)", code, o.URL, dataLen)
+				codeErr := fmt.Errorf("error %d for %s (%d body bytes)", code, o.URL, dataLen)
+				aborter.RecordStart()
+				return NewErrorResult(o, "initial http error", codeErr), codeErr
 			}
 			if i == 0 && log.LogVerbose() {
 				log.LogVf("first hit of url %s: status %03d, headers %d, total %d", o.URL, code, headerSize, dataLen)
@@ -168,7 +193,7 @@ func RunHTTPTest(o *HTTPRunnerOptions) (*HTTPRunnerResults, error) {
 			})
 		}
 		if err := warmup.Wait(); err != nil {
-			return nil, err
+			return NewErrorResult(o, "warmup error", err), err
 		}
 	}
 	// TODO avoid copy pasta with grpcrunner

go.mod

@@ -6,8 +6,8 @@ require (
 	fortio.org/assert v1.2.0
 	fortio.org/cli v1.2.0
 	fortio.org/dflag v1.5.2
-	fortio.org/log v1.7.0
-	fortio.org/scli v1.8.0
+	fortio.org/log v1.8.1
+	fortio.org/scli v1.9.0
 	fortio.org/testscript v0.3.1
 	fortio.org/version v1.0.2
 	github.com/golang/protobuf v1.5.3
@@ -29,7 +29,7 @@ require (
 require (
 	fortio.org/sets v1.0.3 // indirect
 	github.com/fsnotify/fsnotify v1.6.0 // indirect
-	golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53 // indirect
+	golang.org/x/exp v0.0.0-20230713183714-613f0c0eb8a1 // indirect
 	golang.org/x/sys v0.10.0 // indirect
 	golang.org/x/text v0.11.0 // indirect
 	golang.org/x/tools v0.8.0 // indirect

go.sum

@@ -4,10 +4,10 @@ fortio.org/cli v1.2.0 h1:MXmbYnbNHcclf0xYLZjeCnTINby7FpooJxR01+hnBmM=
 fortio.org/cli v1.2.0/go.mod h1:zJwHjRnvVqneF7ES+REfElc33xMjhbRDJslSrqIK9Kk=
 fortio.org/dflag v1.5.2 h1:F9XVRj4Qr2IbJP7BMj7XZc9wB0Q/RZ61Ool+4YPVad8=
 fortio.org/dflag v1.5.2/go.mod h1:ppb/A8u+KKg+qUUYZNYuvRnXuVb8IsdHb/XGzsmjkN8=
-fortio.org/log v1.7.0 h1:4MbU81zqe/3RYuHpXADNgJwd2KEMAwmMUtuF5qtZTug=
-fortio.org/log v1.7.0/go.mod h1:u/8/2lyczXq52aT5Nw6reD+3cR6m/EbS2jBiIYhgiTU=
-fortio.org/scli v1.8.0 h1:JKxPdHeb1vAXFmaliPkfz0Eq2VI35LVUKileOfxdgks=
-fortio.org/scli v1.8.0/go.mod h1:QdIJu32otZ3yGztI3NZoUriMZchXq06u2Ttp+/Tm6u8=
+fortio.org/log v1.8.1 h1:Ybtjp+qDXb124ESnZ0XVuXJ6khDrWcom/C55YPupoKg=
+fortio.org/log v1.8.1/go.mod h1:u/8/2lyczXq52aT5Nw6reD+3cR6m/EbS2jBiIYhgiTU=
+fortio.org/scli v1.9.0 h1:laTn/mACr1+TRKH3ZKaQWw58kTzQ1ntpg2sH02KUJAA=
+fortio.org/scli v1.9.0/go.mod h1:Ox3nhp3eJpF2rQsZ8fBKXqdJGQPTQHWEZpLikDnkzjY=
 fortio.org/sets v1.0.3 h1:HzewdGjH69YmyW06yzplL35lGr+X4OcqQt0qS6jbaO4=
 fortio.org/sets v1.0.3/go.mod h1:QZVj0r6KP/ZD9ebySW9SgxVNy/NjghUfyHW9NN+WU+4=
 fortio.org/testscript v0.3.1 h1:MmRO64AsmzaU1KlYMzAbotJIMKRGxD1XXssJnBRiMGQ=
@@ -23,8 +23,8 @@ github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/
 github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38=
 github.com/google/uuid v1.3.0 h1:t6JiXgmwXMjEs8VusXIJk2BXHsn+wx8BZdTaoZ5fu7I=
 github.com/google/uuid v1.3.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
-golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53 h1:5llv2sWeaMSnA3w2kS57ouQQ4pudlXrR0dCgw51QK9o=
-golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53/go.mod h1:V1LtkGg67GoY2N1AnLN78QLrzxkLyJw7RJb1gzOOz9w=
+golang.org/x/exp v0.0.0-20230713183714-613f0c0eb8a1 h1:MGwJjxBy0HJshjDNfLsYO8xppfqWlA5ZT9OhtUUhTNw=
+golang.org/x/exp v0.0.0-20230713183714-613f0c0eb8a1/go.mod h1:FXUEEKJgO7OQYeo8N01OfiKP8RXMtf6e8aTskBGqWdc=
 golang.org/x/net v0.12.0 h1:cfawfvKITfUsFCeJIHJrbSxpeu/E81khclypR0GVT50=
 golang.org/x/net v0.12.0/go.mod h1:zEVYFnQC7m/vmpQFELhcD1EWkZlX69l4oqgmer6hfKA=
 golang.org/x/sys v0.0.0-20220908164124-27713097b956/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=

periodic/periodic.go

@@ -34,6 +34,7 @@ import (
 	"sync"
 	"time"
 
+	"fortio.org/fortio/jrpc"
 	"fortio.org/fortio/stats"
 	"fortio.org/fortio/version"
 	"fortio.org/log"
@@ -90,6 +91,7 @@ type Aborter struct {
 	stopRequested bool
 }
 
+// Note this can cause data race if called without holding the lock. TODO: maybe use reentrant lock. but this is for debug only.
 func (a *Aborter) String() string {
 	return fmt.Sprintf("{Aborter %p stopChan %v startChan %v hasStarted %v stopRequested %v}",
 		a, a.StopChan, a.StartChan, a.hasStarted, a.stopRequested)
@@ -110,34 +112,53 @@ func (a *Aborter) Abort(wait bool) {
 	a.stopRequested = true
 	started := a.hasStarted
 	if started || !wait {
-		log.LogVf("ABORT Closing %v", a)
+		log.LogVf("ABORT Closing already started or not waiting %v", a)
 		close(a.StopChan)
 		a.StopChan = nil
 		a.Unlock()
 		if started {
 			log.LogVf("ABORT reading start channel")
-			// shouldn't block/hang, just purging/resetting
-			<-a.StartChan
+			// shouldn't block/hang, just purging/resetting - but another aborter (line 137 might have consumed it already)
+			select {
+			case b := <-a.StartChan:
+				log.LogVf("ABORT done reading start channel, got %v", b)
+			default:
+				log.LogVf("ABORT start channel empty (not quite expected)")
+			}
 			a.Lock()
 			a.hasStarted = false
 			a.Unlock()
 		}
 		return
 	}
+	// Wait & not started case:
 	a.Unlock()
 	log.LogVf("ABORT Waiting for start")
-	<-a.StartChan
-	log.LogVf("ABORT Done waiting for start")
+	b := <-a.StartChan
+	log.LogVf("ABORT Done waiting for start, got %v", b)
 	a.Lock()
-	a.hasStarted = false
 	if a.StopChan != nil {
-		log.LogVf("ABORT Closing %+v", a)
+		log.LogVf("ABORT Closing wasn't started %+v", a)
 		close(a.StopChan)
 		a.StopChan = nil
 	}
+	a.hasStarted = false
 	a.Unlock()
 }
 
+// RecordStart records the start of the run. (used by httprunner in error cases to fake start so rapi stop and wait can work).
+func (a *Aborter) RecordStart() (chan struct{}, bool) {
+	a.Lock()
+	a.hasStarted = true
+	startedChan := a.StartChan
+	runnerChan := a.StopChan // need a copy to not race with assignment to nil
+	shouldAbort := a.stopRequested
+	log.LogVf("RUNNER starting... can now be Abort()ed, telling %v - %v", a, startedChan)
+	a.Unlock()
+	startedChan <- true
+	return runnerChan, shouldAbort
+}
+
 // Reset returns the aborter to original state, for (unit test) reuse.
 // Note that it doesn't recreate the closed stop chan.
 func (a *Aborter) Reset() {
@@ -239,6 +260,8 @@ type RunnerResults struct {
 	AccessLoggerInfo        string
 	// Same as RunnerOptions ID:  Unique 96 character ID used as reference to saved json file. Created during Normalize().
 	ID string
+	// If the run doesn't even start because of for instance an invalid host name, this will be set (all omitted on success)
+	jrpc.ServerReply
 }
 
 // HasRunnerResult is the interface implictly implemented by HTTPRunnerResults
@@ -363,7 +386,7 @@ func (r *RunnerOptions) Normalize() {
 // to nil under lock so it can be called multiple times and not create panic for
 // already closed channel.
 func (r *RunnerOptions) Abort() {
-	log.LogVf("Abort called for %p %+v", r, r)
+	log.LogVf("Abort called for %p", r)
 	if r.Stop != nil {
 		r.Stop.Abort(false)
 	}
@@ -473,14 +496,7 @@ func (r *periodicRunner) runMaxQPSSetup(extra string) (requestedDuration string,
 // Run starts the runner.
 func (r *periodicRunner) Run() RunnerResults {
 	aborter := r.Stop
-	aborter.Lock()
-	runnerChan := aborter.StopChan // need a copy to not race with assignment to nil
-	startedChan := aborter.StartChan
-	aborter.hasStarted = true
-	shouldAbort := aborter.stopRequested
-	aborter.Unlock()
-	log.LogVf("RUNNER starting... can now be Abort()ed, telling %v - %v", aborter, startedChan)
-	startedChan <- true
+	runnerChan, shouldAbort := aborter.RecordStart()
 	useQPS := (r.QPS > 0)
 	// r.Exactly is > 0 if we use Exactly iterations instead of the duration.
 	useExactly := (r.Exactly > 0)
@@ -524,6 +540,7 @@ func (r *periodicRunner) Run() RunnerResults {
 			0, 0, 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, r.ID,
+			*jrpc.NewErrorReply("Aborted before even starting", nil),
 		}
 	}
 	if r.NumThreads <= 1 {
@@ -589,6 +606,7 @@ func (r *periodicRunner) Run() RunnerResults {
 		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, r.ID,
+		jrpc.ServerReply{Error: false},
 	}
 	if log.Log(log.Warning) {
 		result.DurationHistogram.Print(r.Out, "Aggregated Function Time")