Add debug log feature (#58)

Author: int128

README.md

@@ -33,10 +33,10 @@ After initial setup or when the token has been expired, just run:
 
 ```
 % kubelogin
-2019/04/09 13:33:37 Using current-context: hello.k8s.local
-2019/04/09 13:33:38 Open http://localhost:8000 for authorization
-2019/04/09 13:33:44 Got a token for subject=1234567890
-2019/04/09 13:33:44 Updated .kubeconfig
+Using current-context: hello.k8s.local
+Open http://localhost:8000 for authorization
+Got a token for subject 0123456789 (valid until 2019-04-12 11:00:49 +0900 JST)
+Updated ~/.kube/config
 ```
 
 or run as a kubectl plugin:
@@ -68,6 +68,7 @@ Application Options:
       --insecure-skip-tls-verify  If set, the server's certificate will not be checked for validity. This will make your HTTPS connections insecure
                                   [$KUBELOGIN_INSECURE_SKIP_TLS_VERIFY]
       --skip-open-browser         If set, it does not open the browser on authentication. [$KUBELOGIN_SKIP_OPEN_BROWSER]
+  -v, --v=                        If set to 1 or greater, show debug log (default: 0)
 
 Help Options:
   -h, --help        Show this help message

adaptors/cmd.go

@@ -30,16 +30,17 @@ func (cmd *Cmd) Run(ctx context.Context, args []string, version string) int {
 		version)
 	args, err := parser.ParseArgs(args[1:])
 	if err != nil {
-		cmd.Logger.Logf("Error: %s", err)
+		cmd.Logger.Printf("Error: %s", err)
 		return 1
 	}
 	if len(args) > 0 {
-		cmd.Logger.Logf("Error: too many arguments")
+		cmd.Logger.Printf("Error: too many arguments")
 		return 1
 	}
+	cmd.Logger.SetLevel(adaptors.LogLevel(o.Verbose))
 	kubeConfig, err := o.ExpandKubeConfig()
 	if err != nil {
-		cmd.Logger.Logf("Error: invalid option: %s", err)
+		cmd.Logger.Printf("Error: invalid option: %s", err)
 		return 1
 	}
 
@@ -50,7 +51,7 @@ func (cmd *Cmd) Run(ctx context.Context, args []string, version string) int {
 		SkipOpenBrowser: o.SkipOpenBrowser,
 	}
 	if err := cmd.Login.Do(ctx, in); err != nil {
-		cmd.Logger.Logf("Error: %s", err)
+		cmd.Logger.Printf("Error: %s", err)
 		return 1
 	}
 	return 0
@@ -61,6 +62,7 @@ type cmdOptions struct {
 	ListenPort      int    `long:"listen-port" default:"8000" env:"KUBELOGIN_LISTEN_PORT" description:"Port used by kubelogin to bind its webserver"`
 	SkipTLSVerify   bool   `long:"insecure-skip-tls-verify" env:"KUBELOGIN_INSECURE_SKIP_TLS_VERIFY" description:"If set, the server's certificate will not be checked for validity. This will make your HTTPS connections insecure"`
 	SkipOpenBrowser bool   `long:"skip-open-browser" env:"KUBELOGIN_SKIP_OPEN_BROWSER" description:"If set, it does not open the browser on authentication."`
+	Verbose         int    `long:"v" short:"v" default:"0" description:"If set to 1 or greater, show debug log"`
 }
 
 // ExpandKubeConfig returns an expanded KubeConfig path.

adaptors/cmd_test.go

@@ -5,6 +5,8 @@ import (
 	"testing"
 
 	"github.com/golang/mock/gomock"
+	"github.com/int128/kubelogin/adaptors/interfaces"
+	"github.com/int128/kubelogin/adaptors/mock_adaptors"
 	"github.com/int128/kubelogin/usecases/interfaces"
 	"github.com/int128/kubelogin/usecases/mock_usecases"
 	"github.com/mitchellh/go-homedir"
@@ -26,9 +28,13 @@ func TestCmd_Run(t *testing.T) {
 				ListenPort: 8000,
 			})
 
+		logger := mock_adaptors.NewLogger(t, ctrl)
+		logger.EXPECT().
+			SetLevel(adaptors.LogLevel(0))
+
 		cmd := Cmd{
 			Login:  login,
-			Logger: t,
+			Logger: logger,
 		}
 		exitCode := cmd.Run(ctx, []string{executable}, version)
 		if exitCode != 0 {
@@ -50,14 +56,19 @@ func TestCmd_Run(t *testing.T) {
 				SkipOpenBrowser: true,
 			})
 
+		logger := mock_adaptors.NewLogger(t, ctrl)
+		logger.EXPECT().
+			SetLevel(adaptors.LogLevel(1))
+
 		cmd := Cmd{
 			Login:  login,
-			Logger: t,
+			Logger: logger,
 		}
 		exitCode := cmd.Run(ctx, []string{executable,
 			"--listen-port", "10080",
 			"--insecure-skip-tls-verify",
 			"--skip-open-browser",
+			"-v1",
 		}, version)
 		if exitCode != 0 {
 			t.Errorf("exitCode wants 0 but %d", exitCode)
@@ -69,7 +80,7 @@ func TestCmd_Run(t *testing.T) {
 		defer ctrl.Finish()
 		cmd := Cmd{
 			Login:  mock_usecases.NewMockLogin(ctrl),
-			Logger: t,
+			Logger: mock_adaptors.NewLogger(t, ctrl),
 		}
 		exitCode := cmd.Run(context.TODO(), []string{executable, "some"}, version)
 		if exitCode != 1 {

adaptors/http.go

@@ -8,26 +8,34 @@ import (
 	"net/http"
 
 	"github.com/int128/kubelogin/adaptors/interfaces"
+	"github.com/int128/kubelogin/infrastructure"
 	"github.com/pkg/errors"
+	"go.uber.org/dig"
 )
 
-func NewHTTP() adaptors.HTTP {
-	return &HTTP{}
+func NewHTTP(i HTTP) adaptors.HTTP {
+	return &i
 }
 
-type HTTP struct{}
+type HTTP struct {
+	dig.In
+	Logger adaptors.Logger
+}
 
 func (*HTTP) NewClientConfig() adaptors.HTTPClientConfig {
 	return &httpClientConfig{
 		certPool: x509.NewCertPool(),
 	}
 }
 
-func (*HTTP) NewClient(config adaptors.HTTPClientConfig) (*http.Client, error) {
+func (h *HTTP) NewClient(config adaptors.HTTPClientConfig) (*http.Client, error) {
 	return &http.Client{
-		Transport: &http.Transport{
-			TLSClientConfig: config.TLSConfig(),
-			Proxy:           http.ProxyFromEnvironment,
+		Transport: &infrastructure.LoggingTransport{
+			Base: &http.Transport{
+				TLSClientConfig: config.TLSConfig(),
+				Proxy:           http.ProxyFromEnvironment,
+			},
+			Logger: h.Logger,
 		},
 	}, nil
 }

adaptors/interfaces/adaptors.go

@@ -9,7 +9,7 @@ import (
 	"k8s.io/client-go/tools/clientcmd/api"
 )
 
-//go:generate mockgen -package mock_adaptors -destination ../mock_adaptors/mock_adaptors.go github.com/int128/kubelogin/adaptors/interfaces KubeConfig,HTTP,HTTPClientConfig,OIDC
+//go:generate mockgen -package mock_adaptors -destination ../mock_adaptors/mock_adaptors.go github.com/int128/kubelogin/adaptors/interfaces KubeConfig,HTTP,HTTPClientConfig,OIDC,Logger
 
 type Cmd interface {
 	Run(ctx context.Context, args []string, version string) int
@@ -66,5 +66,17 @@ type OIDCVerifyTokenIn struct {
 }
 
 type Logger interface {
-	Logf(format string, v ...interface{})
+	Printf(format string, v ...interface{})
+	Debugf(level LogLevel, format string, v ...interface{})
+	SetLevel(level LogLevel)
+	IsEnabled(level LogLevel) bool
 }
+
+// LogLevel represents a log level for debug.
+//
+// 0 = None
+// 1 = Including in/out
+// 2 = Including transport headers
+// 3 = Including transport body
+//
+type LogLevel int

adaptors/logger.go

@@ -2,16 +2,48 @@ package adaptors
 
 import (
 	"log"
+	"os"
 
 	"github.com/int128/kubelogin/adaptors/interfaces"
 )
 
+// NewLogger returns a Logger with the standard log.Logger for messages and debug.
 func NewLogger() adaptors.Logger {
-	return &Logger{}
+	return &Logger{
+		stdLogger:   log.New(os.Stderr, "", 0),
+		debugLogger: log.New(os.Stderr, "", log.Ltime|log.Lmicroseconds),
+	}
 }
 
-type Logger struct{}
+// NewLoggerWith returns a Logger with the given standard log.Logger.
+func NewLoggerWith(l stdLogger) *Logger {
+	return &Logger{
+		stdLogger:   l,
+		debugLogger: l,
+	}
+}
+
+type stdLogger interface {
+	Printf(format string, v ...interface{})
+}
+
+// Logger wraps the standard log.Logger and just provides debug level.
+type Logger struct {
+	stdLogger
+	debugLogger stdLogger
+	level       adaptors.LogLevel
+}
+
+func (l *Logger) Debugf(level adaptors.LogLevel, format string, v ...interface{}) {
+	if l.IsEnabled(level) {
+		l.debugLogger.Printf(format, v...)
+	}
+}
+
+func (l *Logger) SetLevel(level adaptors.LogLevel) {
+	l.level = level
+}
 
-func (*Logger) Logf(format string, v ...interface{}) {
-	log.Printf(format, v...)
+func (l *Logger) IsEnabled(level adaptors.LogLevel) bool {
+	return level <= l.level
 }

adaptors/logger_test.go

@@ -0,0 +1,53 @@
+package adaptors
+
+import (
+	"fmt"
+	"testing"
+
+	"github.com/int128/kubelogin/adaptors/interfaces"
+)
+
+type mockStdLogger struct {
+	count int
+}
+
+func (l *mockStdLogger) Printf(format string, v ...interface{}) {
+	l.count++
+}
+
+func TestLogger_Debugf(t *testing.T) {
+	for _, c := range []struct {
+		loggerLevel adaptors.LogLevel
+		debugfLevel adaptors.LogLevel
+		count       int
+	}{
+		{0, 0, 1},
+		{0, 1, 0},
+
+		{1, 0, 1},
+		{1, 1, 1},
+		{1, 2, 0},
+
+		{2, 1, 1},
+		{2, 2, 1},
+		{2, 3, 0},
+	} {
+		t.Run(fmt.Sprintf("%+v", c), func(t *testing.T) {
+			m := &mockStdLogger{}
+			l := &Logger{debugLogger: m, level: c.loggerLevel}
+			l.Debugf(c.debugfLevel, "hello")
+			if m.count != c.count {
+				t.Errorf("count wants %d but %d", c.count, m.count)
+			}
+		})
+	}
+}
+
+func TestLogger_Printf(t *testing.T) {
+	m := &mockStdLogger{}
+	l := &Logger{stdLogger: m}
+	l.Printf("hello")
+	if m.count != 1 {
+		t.Errorf("count wants %d but %d", 1, m.count)
+	}
+}

adaptors/mock_adaptors/logger.go

@@ -0,0 +1,31 @@
+package mock_adaptors
+
+import (
+	"github.com/golang/mock/gomock"
+	"github.com/int128/kubelogin/adaptors/interfaces"
+)
+
+func NewLogger(t testingLogger, ctrl *gomock.Controller) *Logger {
+	return &Logger{
+		MockLogger:    NewMockLogger(ctrl),
+		testingLogger: t,
+	}
+}
+
+type testingLogger interface {
+	Logf(format string, v ...interface{})
+}
+
+// Logger provides mock feature but overrides output methods with actual logging.
+type Logger struct {
+	*MockLogger
+	testingLogger testingLogger
+}
+
+func (l *Logger) Printf(format string, v ...interface{}) {
+	l.testingLogger.Logf(format, v...)
+}
+
+func (l *Logger) Debugf(level adaptors.LogLevel, format string, v ...interface{}) {
+	l.testingLogger.Logf(format, v...)
+}