From bbaf47fa0cb97ad8efeb6e7e0c68ef519a4ca1e5 Mon Sep 17 00:00:00 2001 From: Jonas Kaninda Date: Sun, 10 Nov 2024 19:58:53 +0100 Subject: [PATCH] feat: add log level for better debugging --- cmd/server.go | 1 + docs/quickstart/gateway.md | 3 +- docs/quickstart/logging.md | 30 +++++++++++++ docs/quickstart/ssl.md | 2 +- internal/config.go | 16 ++++++- internal/handler.go | 6 +-- internal/middleware/error-interceptor.go | 2 +- internal/middleware/middleware.go | 10 +++-- internal/middleware/rate-limit.go | 2 +- internal/proxy.go | 2 + internal/types.go | 1 + pkg/logger/logger.go | 55 +++++++++++++----------- util/helpers.go | 8 ++-- 13 files changed, 96 insertions(+), 42 deletions(-) create mode 100644 docs/quickstart/logging.md diff --git a/cmd/server.go b/cmd/server.go index a8fd173..0fa3531 100644 --- a/cmd/server.go +++ b/cmd/server.go @@ -41,6 +41,7 @@ var ServerCmd = &cobra.Command{ if err != nil { logger.Fatal("Could not load configuration: %v", err) } + gs.SetEnv() if err := gs.Start(ctx); err != nil { logger.Fatal("Could not start server: %v", err) diff --git a/docs/quickstart/gateway.md b/docs/quickstart/gateway.md index 76bd28d..ee0efa0 100644 --- a/docs/quickstart/gateway.md +++ b/docs/quickstart/gateway.md @@ -16,9 +16,10 @@ gateway: readTimeout: 15 idleTimeout: 30 # Rate limiting - rateLimiter: 0 + rateLimit: 0 accessLog: /dev/Stdout errorLog: /dev/stderr + logLevel: info disableRouteHealthCheckError: false disableDisplayRouteOnStart: false disableKeepAlive: false diff --git a/docs/quickstart/logging.md b/docs/quickstart/logging.md new file mode 100644 index 0000000..240484a --- /dev/null +++ b/docs/quickstart/logging.md @@ -0,0 +1,30 @@ +--- +title: General troubleshooting steps +layout: default +parent: Quickstart +nav_order: 6 +--- + + +# Logging + +### Set the log level to TRACE + +Setting the log level to trace configures the server to trace-log all the headers given in forward auth requests. + +This is helpful to confirm that certain required Headers are correctly forwarded from the reverse proxy. + + + +### When using the environment variable + +Set the Goma log level to TRACE: + +Add the following block to your .env file: +```shell +GOMA_LOG_LEVEL=trace +``` + +### When using a configuration file + +Edit the Goma settings and set `logLevel: trace`. diff --git a/docs/quickstart/ssl.md b/docs/quickstart/ssl.md index 2eea6b4..671de14 100644 --- a/docs/quickstart/ssl.md +++ b/docs/quickstart/ssl.md @@ -2,7 +2,7 @@ title: SSL Certificate layout: default parent: Quickstart -nav_order: 4 +nav_order: 5 --- diff --git a/internal/config.go b/internal/config.go index 5baf3d4..9dc1f7f 100644 --- a/internal/config.go +++ b/internal/config.go @@ -102,9 +102,19 @@ func (GatewayServer) Config(configFile string) (*GatewayServer, error) { middlewares: c.Middlewares, }, nil } -func GetConfigPaths() string { - return util.GetStringEnv("GOMAY_CONFIG_FILE", ConfigFile) + +// SetEnv sets environment variables +func (gatewayServer GatewayServer) SetEnv() { + util.SetEnv("GOMA_LOG_LEVEL", gatewayServer.gateway.LogLevel) + util.SetEnv("GOMA_ERROR_LOG", gatewayServer.gateway.ErrorLog) + util.SetEnv("GOMA_ACCESS_LOG", gatewayServer.gateway.AccessLog) } + +func GetConfigPaths() string { + return util.GetStringEnv("GOMA_CONFIG_FILE", ConfigFile) +} + +// InitConfig initializes configs func InitConfig(cmd *cobra.Command) { configFile, _ := cmd.Flags().GetString("output") if configFile == "" { @@ -114,6 +124,8 @@ func InitConfig(cmd *cobra.Command) { return } + +// initConfig initializes configs func initConfig(configFile string) { if configFile == "" { configFile = GetConfigPaths() diff --git a/internal/handler.go b/internal/handler.go index bf11111..1fb556b 100644 --- a/internal/handler.go +++ b/internal/handler.go @@ -65,7 +65,7 @@ func ProxyErrorHandler(w http.ResponseWriter, r *http.Request, err error) { // HealthCheckHandler handles health check of routes func (heathRoute HealthCheckRoute) HealthCheckHandler(w http.ResponseWriter, r *http.Request) { - logger.Info("%s %s %s %s", r.Method, r.RemoteAddr, r.URL, r.UserAgent()) + logger.Debug("%s %s %s %s", r.Method, r.RemoteAddr, r.URL, r.UserAgent()) wg := sync.WaitGroup{} wg.Add(len(heathRoute.Routes)) var routes []HealthCheckRouteResponse @@ -80,11 +80,11 @@ func (heathRoute HealthCheckRoute) HealthCheckHandler(w http.ResponseWriter, r * } routes = append(routes, HealthCheckRouteResponse{Name: route.Name, Status: "unhealthy", Error: "Error: " + err.Error()}) } else { - logger.Info("Route %s is healthy", route.Name) + logger.Debug("Route %s is healthy", route.Name) routes = append(routes, HealthCheckRouteResponse{Name: route.Name, Status: "healthy", Error: ""}) } } else { - logger.Warn("Route %s's healthCheck is undefined", route.Name) + logger.Debug("Route %s's healthCheck is undefined", route.Name) routes = append(routes, HealthCheckRouteResponse{Name: route.Name, Status: "undefined", Error: ""}) } }() diff --git a/internal/middleware/error-interceptor.go b/internal/middleware/error-interceptor.go index d83f37b..76235c4 100644 --- a/internal/middleware/error-interceptor.go +++ b/internal/middleware/error-interceptor.go @@ -46,7 +46,7 @@ func (intercept InterceptErrors) ErrorInterceptor(next http.Handler) http.Handle rec := newResponseRecorder(w) next.ServeHTTP(rec, r) if canIntercept(rec.statusCode, intercept.Errors) { - logger.Error("Backend error") + logger.Debug("Backend error") logger.Error("An error occurred from the backend with the status code: %d", rec.statusCode) w.Header().Set("Content-Type", "application/json") //Update Origin Cors Headers diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index 48863bc..c8fa848 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -82,6 +82,7 @@ func (jwtAuth JwtAuth) AuthMiddleware(next http.Handler) http.Handler { } return } + logger.Trace("JWT Auth response headers: %v", authReq.Header) // Copy headers from the original request to the new request for name, values := range r.Header { for _, value := range values { @@ -96,8 +97,8 @@ func (jwtAuth JwtAuth) AuthMiddleware(next http.Handler) http.Handler { client := &http.Client{} authResp, err := client.Do(authReq) if err != nil || authResp.StatusCode != http.StatusOK { - logger.Info("%s %s %s %s", r.Method, getRealIP(r), r.URL, r.UserAgent()) - logger.Warn("Proxy authentication error") + logger.Debug("%s %s %s %s", r.Method, getRealIP(r), r.URL, r.UserAgent()) + logger.Debug("Proxy authentication error") w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusUnauthorized) err = json.NewEncoder(w).Encode(ProxyResponseError{ @@ -139,10 +140,11 @@ func (jwtAuth JwtAuth) AuthMiddleware(next http.Handler) http.Handler { // AuthMiddleware checks for the Authorization header and verifies the credentials func (basicAuth AuthBasic) AuthMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + logger.Trace("Basic-Auth request headers: %v", r.Header) // Get the Authorization header authHeader := r.Header.Get("Authorization") if authHeader == "" { - logger.Error("Proxy error, missing Authorization header") + logger.Debug("Proxy error, missing Authorization header") w.Header().Set("WWW-Authenticate", `Basic realm="Restricted"`) w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusUnauthorized) @@ -175,7 +177,7 @@ func (basicAuth AuthBasic) AuthMiddleware(next http.Handler) http.Handler { // Decode the base64 encoded username:password string payload, err := base64.StdEncoding.DecodeString(authHeader[len("Basic "):]) if err != nil { - logger.Error("Proxy error, missing Basic Authorization header") + logger.Debug("Proxy error, missing Basic Authorization header") w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusUnauthorized) err := json.NewEncoder(w).Encode(ProxyResponseError{ diff --git a/internal/middleware/rate-limit.go b/internal/middleware/rate-limit.go index 200b21b..125a10c 100644 --- a/internal/middleware/rate-limit.go +++ b/internal/middleware/rate-limit.go @@ -66,7 +66,7 @@ func (rl *RateLimiter) RateLimitMiddleware() mux.MiddlewareFunc { rl.mu.Unlock() if client.RequestCount > rl.Requests { - logger.Error("Too many requests from IP: %s %s %s", clientID, r.URL, r.UserAgent()) + logger.Debug("Too many requests from IP: %s %s %s", clientID, r.URL, r.UserAgent()) w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusTooManyRequests) //Update Origin Cors Headers diff --git a/internal/proxy.go b/internal/proxy.go index 7188603..ddfbdbd 100644 --- a/internal/proxy.go +++ b/internal/proxy.go @@ -30,6 +30,8 @@ import ( func (proxyRoute ProxyRoute) ProxyHandler() http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { logger.Info("%s %s %s %s", r.Method, getRealIP(r), r.URL.Path, r.UserAgent()) + logger.Trace("Request params: %s", r.URL.RawQuery) + logger.Trace("Request Headers: %s", r.Header) // Check Method if is allowed if len(proxyRoute.methods) > 0 { if !slices.Contains(proxyRoute.methods, r.Method) { diff --git a/internal/types.go b/internal/types.go index 7fa4700..e2923dd 100644 --- a/internal/types.go +++ b/internal/types.go @@ -188,6 +188,7 @@ type Gateway struct { BlockCommonExploits bool `yaml:"blockCommonExploits"` AccessLog string `yaml:"accessLog" env:"GOMA_ACCESS_LOG, overwrite"` ErrorLog string `yaml:"errorLog" env:"GOMA_ERROR_LOG=, overwrite"` + LogLevel string `yaml:"logLevel" env:"GOMA_LOG_LEVEL, overwrite"` // DisableHealthCheckStatus enable and disable routes health check DisableHealthCheckStatus bool `yaml:"disableHealthCheckStatus"` // DisableRouteHealthCheckError allows enabling and disabling backend healthcheck errors diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index 2dd7793..278b4bc 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -33,23 +33,15 @@ type Logger struct { // Info returns info log func Info(msg string, args ...interface{}) { log.SetOutput(getStd(util.GetStringEnv("GOMA_ACCESS_LOG", "/dev/stdout"))) - formattedMessage := fmt.Sprintf(msg, args...) - if len(args) == 0 { - log.Printf("INFO: %s\n", msg) - } else { - log.Printf("INFO: %s\n", formattedMessage) - } + logWithCaller("INFO", msg, args...) + } // Warn returns warning log func Warn(msg string, args ...interface{}) { log.SetOutput(getStd(util.GetStringEnv("GOMA_ACCESS_LOG", "/dev/stdout"))) - formattedMessage := fmt.Sprintf(msg, args...) - if len(args) == 0 { - log.Printf("WARN: %s\n", msg) - } else { - log.Printf("WARN: %s\n", formattedMessage) - } + logWithCaller("WARN", msg, args...) + } // Error logs error messages @@ -60,36 +52,47 @@ func Error(msg string, args ...interface{}) { func Fatal(msg string, args ...interface{}) { log.SetOutput(os.Stdout) - formattedMessage := fmt.Sprintf(msg, args...) - if len(args) == 0 { - log.Printf("ERROR: %s\n", msg) - } else { - log.Printf("ERROR: %s\n", formattedMessage) - } - + logWithCaller("ERROR", msg, args...) os.Exit(1) } func Debug(msg string, args ...interface{}) { log.SetOutput(getStd(util.GetStringEnv("GOMA_ACCESS_LOG", "/dev/stdout"))) - logWithCaller("DEBUG", msg, args...) + logLevel := util.GetStringEnv("GOMA_LOG_LEVEL", "") + if logLevel == "trace" || logLevel == "debug" { + logWithCaller("DEBUG", msg, args...) + } + +} +func Trace(msg string, args ...interface{}) { + log.SetOutput(getStd(util.GetStringEnv("GOMA_ACCESS_LOG", "/dev/stdout"))) + logLevel := util.GetStringEnv("GOMA_LOG_LEVEL", "") + if logLevel == "trace" { + logWithCaller("DEBUG", msg, args...) + } } // Helper function to format and log messages with file and line number func logWithCaller(level, msg string, args ...interface{}) { - formattedMessage := fmt.Sprintf(msg, args...) - _, file, line, ok := runtime.Caller(2) // Get the caller's file and line number (skip 2 frames) + // Format message if there are additional arguments + formattedMessage := msg + if len(args) > 0 { + formattedMessage = fmt.Sprintf(msg, args...) + } + // Get the caller's file and line number (skip 2 frames) + _, file, line, ok := runtime.Caller(2) if !ok { file = "unknown" line = 0 } - - if len(args) == 0 { - log.Printf("%s: %s (File: %s, Line: %d)\n", level, msg, file, line) - } else { + // Log message with caller information if GOMA_LOG_LEVEL is trace + logLevel := util.GetStringEnv("GOMA_LOG_LEVEL", "") + if logLevel == "trace" { log.Printf("%s: %s (File: %s, Line: %d)\n", level, formattedMessage, file, line) + } else { + log.Printf("%s: %s\n", level, formattedMessage) } } diff --git a/util/helpers.go b/util/helpers.go index a78464a..3706784 100644 --- a/util/helpers.go +++ b/util/helpers.go @@ -73,9 +73,11 @@ func GetBoolEnv(key string, defaultValue bool) bool { // SetEnv Set env func SetEnv(name, value string) { - err := os.Setenv(name, value) - if err != nil { - return + if len(value) != 0 { + err := os.Setenv(name, value) + if err != nil { + return + } } }