From 539e92c95b038b2284ecebc514c674426c40cfd7 Mon Sep 17 00:00:00 2001 From: divolgin Date: Wed, 22 Sep 2021 17:44:24 +0000 Subject: [PATCH] Clean up logging and log failed API requests --- kustomize/overlays/dev/deployment.yaml | 2 + pkg/apiserver/server.go | 36 ++++--- pkg/handlers/handlers.go | 2 +- pkg/handlers/middleware.go | 65 +++++++++--- pkg/logger/clilogger.go | 138 ++++++++++++++----------- pkg/operator/client/hooks.go | 11 +- 6 files changed, 157 insertions(+), 97 deletions(-) diff --git a/kustomize/overlays/dev/deployment.yaml b/kustomize/overlays/dev/deployment.yaml index 86a07728da..679a7acca8 100644 --- a/kustomize/overlays/dev/deployment.yaml +++ b/kustomize/overlays/dev/deployment.yaml @@ -72,6 +72,8 @@ spec: value: "3" - name: POD_OWNER_KIND value: "deployment" + - name: DEBUG + value: "false" volumes: - emptyDir: medium: Memory diff --git a/pkg/apiserver/server.go b/pkg/apiserver/server.go index 2ca1f1f358..c9fc694580 100644 --- a/pkg/apiserver/server.go +++ b/pkg/apiserver/server.go @@ -129,38 +129,44 @@ func Start(params *APIServerParams) { r := mux.NewRouter() - r.Use(handlers.LoggingMiddleware, handlers.CorsMiddleware) + r.Use(handlers.CorsMiddleware) r.Methods("OPTIONS").HandlerFunc(handlers.CORS) + debugRouter := r.NewRoute().Subrouter() + debugRouter.Use(handlers.DebugLoggingMiddleware) + + loggingRouter := r.NewRoute().Subrouter() + loggingRouter.Use(handlers.LoggingMiddleware) + handler := &handlers.Handler{} /********************************************************************** * Unauthenticated routes **********************************************************************/ - r.HandleFunc("/healthz", handler.Healthz) - r.HandleFunc("/api/v1/login", handler.Login) - r.HandleFunc("/api/v1/login/info", handler.GetLoginInfo) - r.HandleFunc("/api/v1/logout", handler.Logout) // this route uses its own auth - r.Path("/api/v1/metadata").Methods("GET").HandlerFunc(handler.Metadata) + debugRouter.HandleFunc("/healthz", handler.Healthz) + loggingRouter.HandleFunc("/api/v1/login", handler.Login) + loggingRouter.HandleFunc("/api/v1/login/info", handler.GetLoginInfo) + loggingRouter.HandleFunc("/api/v1/logout", handler.Logout) // this route uses its own auth + loggingRouter.Path("/api/v1/metadata").Methods("GET").HandlerFunc(handler.Metadata) - r.HandleFunc("/api/v1/oidc/login", handler.OIDCLogin) - r.HandleFunc("/api/v1/oidc/login/callback", handler.OIDCLoginCallback) + loggingRouter.HandleFunc("/api/v1/oidc/login", handler.OIDCLogin) + loggingRouter.HandleFunc("/api/v1/oidc/login/callback", handler.OIDCLoginCallback) - r.Path("/api/v1/troubleshoot/{appId}/{bundleId}").Methods("PUT").HandlerFunc(handler.UploadSupportBundle) - r.Path("/api/v1/troubleshoot/supportbundle/{bundleId}/redactions").Methods("PUT").HandlerFunc(handler.SetSupportBundleRedactions) + loggingRouter.Path("/api/v1/troubleshoot/{appId}/{bundleId}").Methods("PUT").HandlerFunc(handler.UploadSupportBundle) + loggingRouter.Path("/api/v1/troubleshoot/supportbundle/{bundleId}/redactions").Methods("PUT").HandlerFunc(handler.SetSupportBundleRedactions) // This the handler for license API and should be called by the application only. - r.Path("/license/v1/license").Methods("GET").HandlerFunc(handler.GetPlatformLicenseCompatibility) + loggingRouter.Path("/license/v1/license").Methods("GET").HandlerFunc(handler.GetPlatformLicenseCompatibility) /********************************************************************** * KOTS token auth routes **********************************************************************/ - r.Path("/api/v1/kots/ports").Methods("GET").HandlerFunc(handler.GetApplicationPorts) - r.Path("/api/v1/upload").Methods("PUT").HandlerFunc(handler.UploadExistingApp) - r.Path("/api/v1/download").Methods("GET").HandlerFunc(handler.DownloadApp) - r.Path("/api/v1/airgap/install").Methods("POST").HandlerFunc(handler.UploadInitialAirgapApp) + debugRouter.Path("/api/v1/kots/ports").Methods("GET").HandlerFunc(handler.GetApplicationPorts) + loggingRouter.Path("/api/v1/upload").Methods("PUT").HandlerFunc(handler.UploadExistingApp) + loggingRouter.Path("/api/v1/download").Methods("GET").HandlerFunc(handler.DownloadApp) + loggingRouter.Path("/api/v1/airgap/install").Methods("POST").HandlerFunc(handler.UploadInitialAirgapApp) /********************************************************************** * Session auth routes diff --git a/pkg/handlers/handlers.go b/pkg/handlers/handlers.go index 5485b7ec14..7c6aaf56cb 100644 --- a/pkg/handlers/handlers.go +++ b/pkg/handlers/handlers.go @@ -28,7 +28,7 @@ func init() { } func RegisterSessionAuthRoutes(r *mux.Router, kotsStore store.Store, handler KOTSHandler, middleware *policy.Middleware) { - r.Use(RequireValidSessionMiddleware(kotsStore)) + r.Use(LoggingMiddleware, RequireValidSessionMiddleware(kotsStore)) // Installation r.Name("UploadNewLicense").Path("/api/v1/license").Methods("POST"). diff --git a/pkg/handlers/middleware.go b/pkg/handlers/middleware.go index 12eb94bf52..ea328f8a89 100644 --- a/pkg/handlers/middleware.go +++ b/pkg/handlers/middleware.go @@ -12,6 +12,20 @@ import ( "github.com/replicatedhq/kots/pkg/store" ) +type loggingResponseWriter struct { + http.ResponseWriter + StatusCode int +} + +func NewLoggingResponseWriter(w http.ResponseWriter) *loggingResponseWriter { + return &loggingResponseWriter{w, http.StatusOK} +} + +func (lrw *loggingResponseWriter) WriteHeader(code int) { + lrw.StatusCode = code + lrw.ResponseWriter.WriteHeader(code) +} + func CorsMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if handleOptionsRequest(w, r) { @@ -21,23 +35,46 @@ func CorsMiddleware(next http.Handler) http.Handler { }) } +func DebugLoggingMiddleware(next http.Handler) http.Handler { + if os.Getenv("DEBUG") != "true" { + return next + } + + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + startTime := time.Now() + + lrw := NewLoggingResponseWriter(w) + next.ServeHTTP(lrw, r) + + logger.Debugf( + "method=%s status=%d duration=%s request=%s", + r.Method, + lrw.StatusCode, + time.Since(startTime).String(), + r.RequestURI, + ) + }) +} + func LoggingMiddleware(next http.Handler) http.Handler { - debug := os.Getenv("DEBUG") == "true" - if debug { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - startTime := time.Now() + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + startTime := time.Now() - next.ServeHTTP(w, r) + lrw := NewLoggingResponseWriter(w) + next.ServeHTTP(lrw, r) - logger.Debugf( - "request=%s method=%s duration=%s", - r.RequestURI, - r.Method, - time.Since(startTime).String(), - ) - }) - } - return next + if os.Getenv("DEBUG") != "true" && lrw.StatusCode < http.StatusBadRequest { + return + } + + logger.Infof( + "method=%s status=%d duration=%s request=%s", + r.Method, + lrw.StatusCode, + time.Since(startTime).String(), + r.RequestURI, + ) + }) } func RequireValidSessionMiddleware(kotsStore store.Store) mux.MiddlewareFunc { diff --git a/pkg/logger/clilogger.go b/pkg/logger/clilogger.go index a18bb7dc77..12c5222665 100644 --- a/pkg/logger/clilogger.go +++ b/pkg/logger/clilogger.go @@ -103,29 +103,32 @@ func (l *CLILogger) ActionWithSpinner(msg string, args ...interface{}) { fmt.Printf(" • ") fmt.Printf(msg, args...) - if isatty.IsTerminal(os.Stdout.Fd()) { - s := spin.New() - - fmt.Printf(" %s", s.Next()) - - l.spinnerStopCh = make(chan bool) - l.spinnerMsg = msg - l.spinnerArgs = args - - go func() { - for { - select { - case <-l.spinnerStopCh: - return - case <-time.After(time.Millisecond * 100): - fmt.Printf("\r") - fmt.Printf(" • ") - fmt.Printf(msg, args...) - fmt.Printf(" %s", s.Next()) - } - } - }() + if !isatty.IsTerminal(os.Stdout.Fd()) { + fmt.Println() + return } + + s := spin.New() + + fmt.Printf(" %s", s.Next()) + + l.spinnerStopCh = make(chan bool) + l.spinnerMsg = msg + l.spinnerArgs = args + + go func() { + for { + select { + case <-l.spinnerStopCh: + return + case <-time.After(time.Millisecond * 100): + fmt.Printf("\r") + fmt.Printf(" • ") + fmt.Printf(msg, args...) + fmt.Printf(" %s", s.Next()) + } + } + }() } func (l *CLILogger) ChildActionWithSpinner(msg string, args ...interface{}) { @@ -136,29 +139,32 @@ func (l *CLILogger) ChildActionWithSpinner(msg string, args ...interface{}) { fmt.Printf(" • ") fmt.Printf(msg, args...) - if isatty.IsTerminal(os.Stdout.Fd()) { - s := spin.New() - - fmt.Printf(" %s", s.Next()) - - l.spinnerStopCh = make(chan bool) - l.spinnerMsg = msg - l.spinnerArgs = args - - go func() { - for { - select { - case <-l.spinnerStopCh: - return - case <-time.After(time.Millisecond * 100): - fmt.Printf("\r") - fmt.Printf(" • ") - fmt.Printf(msg, args...) - fmt.Printf(" %s", s.Next()) - } - } - }() + if !isatty.IsTerminal(os.Stdout.Fd()) { + fmt.Println() + return } + + s := spin.New() + + fmt.Printf(" %s", s.Next()) + + l.spinnerStopCh = make(chan bool) + l.spinnerMsg = msg + l.spinnerArgs = args + + go func() { + for { + select { + case <-l.spinnerStopCh: + return + case <-time.After(time.Millisecond * 100): + fmt.Printf("\r") + fmt.Printf(" • ") + fmt.Printf(msg, args...) + fmt.Printf(" %s", s.Next()) + } + } + }() } func (l *CLILogger) FinishChildSpinner() { @@ -166,6 +172,11 @@ func (l *CLILogger) FinishChildSpinner() { return } + if !isatty.IsTerminal(os.Stdout.Fd()) { + fmt.Println(" • ✓") + return + } + green := color.New(color.FgHiGreen) fmt.Printf("\r") @@ -174,10 +185,8 @@ func (l *CLILogger) FinishChildSpinner() { green.Printf(" ✓") fmt.Printf(" \n") - if isatty.IsTerminal(os.Stdout.Fd()) { - l.spinnerStopCh <- true - close(l.spinnerStopCh) - } + l.spinnerStopCh <- true + close(l.spinnerStopCh) } func (l *CLILogger) FinishSpinner() { @@ -185,6 +194,11 @@ func (l *CLILogger) FinishSpinner() { return } + if !isatty.IsTerminal(os.Stdout.Fd()) { + fmt.Println(" • ✓") + return + } + green := color.New(color.FgHiGreen) fmt.Printf("\r") @@ -193,10 +207,8 @@ func (l *CLILogger) FinishSpinner() { green.Printf(" ✓") fmt.Printf(" \n") - if isatty.IsTerminal(os.Stdout.Fd()) { - l.spinnerStopCh <- true - close(l.spinnerStopCh) - } + l.spinnerStopCh <- true + close(l.spinnerStopCh) } func (l *CLILogger) FinishSpinnerWithError() { @@ -204,6 +216,11 @@ func (l *CLILogger) FinishSpinnerWithError() { return } + if !isatty.IsTerminal(os.Stdout.Fd()) { + fmt.Println(" • ✗") + return + } + red := color.New(color.FgHiRed) fmt.Printf("\r") @@ -212,10 +229,8 @@ func (l *CLILogger) FinishSpinnerWithError() { red.Printf(" ✗") fmt.Printf(" \n") - if isatty.IsTerminal(os.Stdout.Fd()) { - l.spinnerStopCh <- true - close(l.spinnerStopCh) - } + l.spinnerStopCh <- true + close(l.spinnerStopCh) } // FinishSpinnerWithWarning if no color is provided, color.FgYellow will be used @@ -224,6 +239,11 @@ func (l *CLILogger) FinishSpinnerWithWarning(c *color.Color) { return } + if !isatty.IsTerminal(os.Stdout.Fd()) { + fmt.Println(" • !") + return + } + if c == nil { c = color.New(color.FgYellow) } @@ -234,10 +254,8 @@ func (l *CLILogger) FinishSpinnerWithWarning(c *color.Color) { c.Printf(" !") fmt.Printf(" \n") - if isatty.IsTerminal(os.Stdout.Fd()) { - l.spinnerStopCh <- true - close(l.spinnerStopCh) - } + l.spinnerStopCh <- true + close(l.spinnerStopCh) } func (l *CLILogger) Error(err error) { diff --git a/pkg/operator/client/hooks.go b/pkg/operator/client/hooks.go index baa4d346bc..fd1019a0d7 100644 --- a/pkg/operator/client/hooks.go +++ b/pkg/operator/client/hooks.go @@ -2,12 +2,12 @@ package client import ( "context" - "fmt" "strings" "time" "github.com/pkg/errors" "github.com/replicatedhq/kots/pkg/k8sutil" + "github.com/replicatedhq/kots/pkg/logger" batchv1 "k8s.io/api/batch/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/fields" @@ -33,7 +33,7 @@ func (c *Client) runHooksInformer(namespace string) error { job, ok := newObj.(*batchv1.Job) if !ok { - fmt.Println("error getting new job") + logger.Errorf("expected batchv1.Job, but got %T", newObj) return } @@ -56,12 +56,9 @@ func (c *Client) runHooksInformer(namespace string) error { } if !cleanUpJob { - fmt.Printf("not cleaning up job %q, active=%d, succeeeded=%d, failed=%d\n", job.Name, job.Status.Active, job.Status.Succeeded, job.Status.Failed) return } - fmt.Printf("attempting to %s delete job %s\n", reason, job.Name) - grace := int64(0) policy := metav1.DeletePropagationBackground opts := metav1.DeleteOptions{ @@ -69,10 +66,10 @@ func (c *Client) runHooksInformer(namespace string) error { PropagationPolicy: &policy, } if err := clientset.BatchV1().Jobs(job.Namespace).Delete(context.TODO(), job.Name, opts); err != nil { - fmt.Printf("error deleting job: %s\n", err.Error()) + logger.Error(errors.Wrap(err, "failed to delete job")) return } - fmt.Printf("deleted %s job %s\n", reason, job.Name) + logger.Debugf("deleted %s job %s\n", reason, job.Name) }, }, )