Add exponential backoff before retrying

go.mod

@@ -3,6 +3,7 @@ module github.com/int128/kauthproxy
 go 1.12
 
 require (
+	github.com/cenkalti/backoff v2.2.1+incompatible
 	github.com/go-test/deep v1.0.4
 	github.com/golang/mock v1.3.1
 	github.com/google/wire v0.3.0

go.sum

@@ -9,6 +9,8 @@ github.com/PuerkitoBio/urlesc v0.0.0-20160726150825-5bd2802263f2/go.mod h1:uGdko
 github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 h1:d+Bc7a5rLufV/sSk/8dngufqelfh6jnri85riMAaF/M=
 github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578/go.mod h1:uGdkoq3SwY9Y+13GIhn11/XLaGBb4BfwItxLd5jeuXE=
 github.com/armon/consul-api v0.0.0-20180202201655-eb2c6b5be1b6/go.mod h1:grANhF5doyWs3UAsr3K4I6qtAmlQcZDesFNEHPZAzj8=
+github.com/cenkalti/backoff v2.2.1+incompatible h1:tNowT99t7UNflLxfYYSlKYsBpXdEet03Pg2g16Swow4=
+github.com/cenkalti/backoff v2.2.1+incompatible/go.mod h1:90ReRw6GdpyfrHakVjL/QHaoyV4aDUVVkXQJJJ3NXXM=
 github.com/coreos/etcd v3.3.10+incompatible/go.mod h1:uF7uidLiAD3TWHmW31ZFd/JWoc32PjwdhPthX9715RE=
 github.com/coreos/go-etcd v2.0.0+incompatible/go.mod h1:Jez6KQU2B/sWsbdaef3ED8NzMklzPG4d5KIOhIy30Tk=
 github.com/coreos/go-semver v0.2.0/go.mod h1:nnelYz7RCh+5ahJtPPxZlU+153eP4D4r3EedlOD2RNk=

pkg/adaptors/logger/mock_logger/mock_logger.go

@@ -1,6 +1,8 @@
 package mock_logger
 
 import (
+	"time"
+
 	logger2 "github.com/int128/kauthproxy/pkg/adaptors/logger"
 	"github.com/spf13/pflag"
 )
@@ -21,7 +23,7 @@ func (l *Logger) AddFlags(f *pflag.FlagSet) {
 }
 
 func (l *Logger) Printf(format string, args ...interface{}) {
-	l.t.Logf(format, args...)
+	logf(l.t, "", format, args)
 }
 
 func (l *Logger) V(level int) logger2.Verbose {
@@ -33,6 +35,12 @@ type Verbose struct {
 }
 
 func (v *Verbose) Infof(format string, args ...interface{}) {
-	v.t.Logf("I] "+format, args...)
-	//log.Printf("I] "+format, args...)
+	logf(v.t, "I]", format, args)
+}
+
+func logf(t testingLogf, level, format string, args []interface{}) {
+	t.Logf("%s %2s "+format, append([]interface{}{
+		time.Now().Format("15:04:05.000"),
+		level,
+	}, args...)...)
 }

pkg/usecases/authproxy/auth_proxy.go

@@ -5,6 +5,7 @@ import (
 	"net/url"
 	"strings"
 
+	"github.com/cenkalti/backoff"
 	"github.com/google/wire"
 	"github.com/int128/kauthproxy/pkg/adaptors/logger"
 	"github.com/int128/kauthproxy/pkg/adaptors/network"
@@ -82,15 +83,20 @@ func (u *AuthProxy) Do(ctx context.Context, o Option) error {
 		TargetHost:            "localhost",
 		TargetPort:            transitPort,
 	}
-	for {
+	b := backoff.NewExponentialBackOff()
+	if err := backoff.Retry(func() error {
 		if err := u.run(ctx, pfo, rpo); err != nil {
 			if xerrors.Is(err, portForwarderConnectionLostError) {
-				continue // retry connection
+				u.Logger.Printf("retrying: %s", err)
+				return err
 			}
-			return xerrors.Errorf("error while running an authentication proxy: %w", err)
+			return backoff.Permanent(err)
 		}
 		return nil
+	}, b); err != nil {
+		return xerrors.Errorf("retry over: %w", err)
 	}
+	return nil
 }
 
 // run runs a port forwarder and reverse proxy, and waits for them, as follows:
@@ -122,6 +128,7 @@ func (u *AuthProxy) run(ctx context.Context, pfo portforwarder.Option, rpo rever
 		}
 		u.Logger.V(1).Infof("stopped the port forwarder")
 		if ctx.Err() == nil {
+			u.Logger.V(1).Infof("connection of the port forwarder has lost")
 			return portForwarderConnectionLostError
 		}
 		return nil

pkg/usecases/authproxy/auth_proxy_test.go

@@ -209,13 +209,15 @@ func TestAuthProxy_Do(t *testing.T) {
 		})
 
 		t.Run("PortForwarderConnectionLost", func(t *testing.T) {
+			// 0ms:   starting
 			// 100ms: the port forwarder is ready
 			// 200ms: the reverse proxy is ready
 			// 400ms: lost connection
-			// 500ms: the port forwarder is ready
-			// 600ms: the reverse proxy is ready
-			// 700ms: cancel the context
-			ctx, cancel := context.WithTimeout(context.TODO(), 700*time.Millisecond)
+			// 900ms: retrying (after the backoff 500ms)
+			// 1000ms: the port forwarder is ready
+			// 1100ms: the reverse proxy is ready
+			// 1200ms: cancel the context
+			ctx, cancel := context.WithTimeout(context.TODO(), 1200*time.Millisecond)
 			defer cancel()
 			ctrl := gomock.NewController(t)
 			defer ctrl.Finish()