Adds ability to change log verbosity through cli / env var and also a…

…dds debug logging statements for upstream requests

Signed-off-by: Alex Creasy <[email protected]>

clients/ui/bff/Makefile

@@ -8,6 +8,7 @@ STANDALONE_MODE ?= true
 STATIC_ASSETS_DIR ?= ./static
 # ENVTEST_K8S_VERSION refers to the version of kubebuilder assets to be downloaded by envtest binary.
 ENVTEST_K8S_VERSION = 1.29.0
+LOG_LEVEL ?= info
 
 .PHONY: all
 all: build
@@ -48,7 +49,7 @@ build: fmt vet test ## Builds the project to produce a binary executable.
 .PHONY: run
 run: fmt vet envtest ## Runs the project.
 	ENVTEST_ASSETS="$(shell $(ENVTEST) use $(ENVTEST_K8S_VERSION) --bin-dir $(LOCALBIN) -p path)" \
-	go run ./cmd/main.go  --port=$(PORT) --static-assets-dir=$(STATIC_ASSETS_DIR) --mock-k8s-client=$(MOCK_K8S_CLIENT) --mock-mr-client=$(MOCK_MR_CLIENT) --dev-mode=$(DEV_MODE) --dev-mode-port=$(DEV_MODE_PORT)  --standalone-mode=$(STANDALONE_MODE)
+	go run ./cmd/main.go  --port=$(PORT) --static-assets-dir=$(STATIC_ASSETS_DIR) --mock-k8s-client=$(MOCK_K8S_CLIENT) --mock-mr-client=$(MOCK_MR_CLIENT) --dev-mode=$(DEV_MODE) --dev-mode-port=$(DEV_MODE_PORT)  --standalone-mode=$(STANDALONE_MODE) --log-level=$(LOG_LEVEL)
 
 ##@ Dependencies
 

clients/ui/bff/cmd/main.go

@@ -5,6 +5,7 @@ import (
 	"flag"
 	"fmt"
 	"os/signal"
+	"strings"
 	"syscall"
 
 	"github.com/kubeflow/model-registry/ui/bff/internal/api"
@@ -26,9 +27,12 @@ func main() {
 	flag.IntVar(&cfg.DevModePort, "dev-mode-port", getEnvAsInt("DEV_MODE_PORT", 8080), "Use port when in development mode")
 	flag.BoolVar(&cfg.StandaloneMode, "standalone-mode", false, "Use standalone mode for enabling endpoints in standalone mode")
 	flag.StringVar(&cfg.StaticAssetsDir, "static-assets-dir", "./static", "Configure frontend static assets root directory")
+	flag.StringVar(&cfg.LogLevel, "log-level", getEnvAsString("LOG_LEVEL", "info"), "Sets server log level, possible values: debug, info, warn, error, fatal")
 	flag.Parse()
 
-	logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
+	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		Level: getLogLevelFromString(cfg.LogLevel),
+	}))
 
 	app, err := api.NewApp(cfg, logger)
 	if err != nil {
@@ -88,3 +92,27 @@ func getEnvAsInt(name string, defaultVal int) int {
 	}
 	return defaultVal
 }
+
+func getEnvAsString(name string, defaultVal string) string {
+	if value, exists := os.LookupEnv(name); exists {
+		return value
+	}
+	return defaultVal
+}
+
+func getLogLevelFromString(level string) slog.Level {
+	switch strings.ToLower(level) {
+	case "debug":
+		return slog.LevelDebug
+	case "info":
+		return slog.LevelInfo
+	case "warn":
+		return slog.LevelWarn
+	case "error":
+		return slog.LevelError
+	case "fatal":
+		return slog.LevelError
+
+	}
+	return slog.LevelInfo
+}

clients/ui/bff/internal/api/app.go

@@ -138,5 +138,5 @@ func (app *App) Routes() http.Handler {
 		http.ServeFile(w, r, path.Join(app.config.StaticAssetsDir, "index.html"))
 	})
 
-	return app.RecoverPanic(app.enableCORS(app.InjectUserHeaders(appMux)))
+	return app.RecoverPanic(app.EnableTelemetry(app.enableCORS(app.InjectUserHeaders(appMux))))
 }

clients/ui/bff/internal/api/middleware.go

@@ -4,12 +4,13 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"net/http"
-	"strings"
-
+	"github.com/google/uuid"
 	"github.com/julienschmidt/httprouter"
 	"github.com/kubeflow/model-registry/ui/bff/internal/config"
 	"github.com/kubeflow/model-registry/ui/bff/internal/integrations"
+	"log/slog"
+	"net/http"
+	"strings"
 )
 
 type contextKey string
@@ -25,6 +26,9 @@ const (
 	KubeflowUserIDHeader                  = "kubeflow-userid"
 	KubeflowUserGroupsKey      contextKey = "kubeflowUserGroups" // kubeflow-groups : Holds a comma-separated list of user groups
 	KubeflowUserGroupsIdHeader            = "kubeflow-groups"
+
+	TraceIdKey     contextKey = "TraceIdKey"
+	TraceLoggerKey contextKey = "TraceLoggerKey"
 )
 
 func (app *App) RecoverPanic(next http.Handler) http.Handler {
@@ -87,6 +91,31 @@ func (app *App) enableCORS(next http.Handler) http.Handler {
 	})
 }
 
+func (app *App) EnableTelemetry(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		// Adds a unique id to the context to allow tracing of requests
+		traceId := uuid.NewString()
+		ctx := context.WithValue(r.Context(), TraceIdKey, traceId)
+
+		// logger will only be nil in tests.
+		if app.logger != nil {
+			traceLogger := app.logger.With(slog.String("trace_id", traceId))
+			ctx = context.WithValue(ctx, TraceLoggerKey, traceLogger)
+
+			if traceLogger.Enabled(ctx, slog.LevelDebug) {
+				cloneBody, err := integrations.CloneBody(r)
+				if err != nil {
+					traceLogger.Debug("Error reading request body for debug logging", "error", err)
+				}
+				////TODO (Alex) Log headers, BUT we must ensure we don't log confidential data like tokens etc.
+				traceLogger.Debug("Incoming HTTP request", "method", r.Method, "url", r.URL.String(), "body", cloneBody)
+			}
+		}
+
+		next.ServeHTTP(w, r.WithContext(ctx))
+	})
+}
+
 func (app *App) AttachRESTClient(next func(http.ResponseWriter, *http.Request, httprouter.Params)) httprouter.Handle {
 	return func(w http.ResponseWriter, r *http.Request, ps httprouter.Params) {
 
@@ -103,7 +132,19 @@ func (app *App) AttachRESTClient(next func(http.ResponseWriter, *http.Request, h
 			return
 		}
 
-		client, err := integrations.NewHTTPClient(modelRegistryID, modelRegistryBaseURL)
+		// Set up a child logger for the rest client that automatically adds the request id to all statements for
+		// tracing.
+		restClientLogger := app.logger
+		traceId, ok := r.Context().Value(TraceIdKey).(string)
+		if app.logger != nil {
+			if ok {
+				restClientLogger = app.logger.With(slog.String("trace_id", traceId))
+			} else {
+				app.logger.Warn("Failed to set trace_id for tracing")
+			}
+		}
+
+		client, err := integrations.NewHTTPClient(restClientLogger, modelRegistryID, modelRegistryBaseURL)
 		if err != nil {
 			app.serverErrorResponse(w, r, fmt.Errorf("failed to create Kubernetes client: %v", err))
 			return

clients/ui/bff/internal/config/environment.go

@@ -8,4 +8,5 @@ type EnvConfig struct {
 	StandaloneMode  bool
 	DevModePort     int
 	StaticAssetsDir string
+	LogLevel        string
 }

clients/ui/bff/internal/integrations/http.go

@@ -1,16 +1,18 @@
 package integrations
 
 import (
+	"context"
 	"crypto/tls"
 	"encoding/json"
 	"fmt"
+	"github.com/google/uuid"
 	"io"
+	"log/slog"
 	"net/http"
 	"strconv"
 )
 
 type HTTPClientInterface interface {
-	GetModelRegistryID() (modelRegistryService string)
 	GET(url string) ([]byte, error)
 	POST(url string, body io.Reader) ([]byte, error)
 	PATCH(url string, body io.Reader) ([]byte, error)
@@ -20,6 +22,7 @@ type HTTPClient struct {
 	client          *http.Client
 	baseURL         string
 	ModelRegistryID string
+	logger          *slog.Logger
 }
 
 type ErrorResponse struct {
@@ -36,14 +39,15 @@ func (e *HTTPError) Error() string {
 	return fmt.Sprintf("HTTP %d: %s - %s", e.StatusCode, e.Code, e.Message)
 }
 
-func NewHTTPClient(modelRegistryID string, baseURL string) (HTTPClientInterface, error) {
+func NewHTTPClient(logger *slog.Logger, modelRegistryID string, baseURL string) (HTTPClientInterface, error) {
 
 	return &HTTPClient{
 		client: &http.Client{Transport: &http.Transport{
 			TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
 		}},
 		baseURL:         baseURL,
 		ModelRegistryID: modelRegistryID,
+		logger:          logger,
 	}, nil
 }
 
@@ -52,26 +56,33 @@ func (c *HTTPClient) GetModelRegistryID() string {
 }
 
 func (c *HTTPClient) GET(url string) ([]byte, error) {
+	requestId := uuid.NewString()
+
 	fullURL := c.baseURL + url
 	req, err := http.NewRequest("GET", fullURL, nil)
 	if err != nil {
 		return nil, err
 	}
 
+	logUpstreamReq(c.logger, requestId, req)
+
 	response, err := c.client.Do(req)
 	if err != nil {
 		return nil, err
 	}
 	defer response.Body.Close()
 
 	body, err := io.ReadAll(response.Body)
+	logUpstreamResp(c.logger, requestId, response, body)
 	if err != nil {
 		return nil, fmt.Errorf("error reading response body: %w", err)
 	}
 	return body, nil
 }
 
 func (c *HTTPClient) POST(url string, body io.Reader) ([]byte, error) {
+	requestId := uuid.NewString()
+
 	fullURL := c.baseURL + url
 	fmt.Println(fullURL)
 	req, err := http.NewRequest("POST", fullURL, body)
@@ -81,13 +92,16 @@ func (c *HTTPClient) POST(url string, body io.Reader) ([]byte, error) {
 
 	req.Header.Set("Content-Type", "application/json")
 
+	logUpstreamReq(c.logger, requestId, req)
+
 	response, err := c.client.Do(req)
 	if err != nil {
 		return nil, err
 	}
 	defer response.Body.Close()
 
 	responseBody, err := io.ReadAll(response.Body)
+	logUpstreamResp(c.logger, requestId, response, responseBody)
 	if err != nil {
 		return nil, fmt.Errorf("error reading response body: %w", err)
 	}
@@ -120,15 +134,20 @@ func (c *HTTPClient) PATCH(url string, body io.Reader) ([]byte, error) {
 		return nil, err
 	}
 
+	requestId := uuid.NewString()
+
 	req.Header.Set("Content-Type", "application/json")
 
+	logUpstreamReq(c.logger, requestId, req)
+
 	response, err := c.client.Do(req)
 	if err != nil {
 		return nil, err
 	}
 	defer response.Body.Close()
 
 	responseBody, err := io.ReadAll(response.Body)
+	logUpstreamResp(c.logger, requestId, response, responseBody)
 	if err != nil {
 		return nil, fmt.Errorf("error reading response body: %w", err)
 	}
@@ -152,3 +171,19 @@ func (c *HTTPClient) PATCH(url string, body io.Reader) ([]byte, error) {
 	}
 	return responseBody, nil
 }
+
+func logUpstreamReq(logger *slog.Logger, reqId string, req *http.Request) {
+	if logger.Enabled(context.TODO(), slog.LevelDebug) {
+		body, err := req.GetBody()
+		if err != nil {
+			logger.Debug("Error reading request body for debug logging", "requestId", reqId, "error", err)
+		}
+		logger.Debug("Making upstream HTTP request", "request_id", reqId, "method", req.Method, "url", req.URL.String(), "body", StreamToString(body))
+	}
+}
+
+func logUpstreamResp(logger *slog.Logger, reqId string, resp *http.Response, body []byte) {
+	if logger.Enabled(context.TODO(), slog.LevelDebug) {
+		logger.Debug("Received upstream HTTP response", "request_id", reqId, "status_code", resp.StatusCode, "body", body)
+	}
+}

clients/ui/bff/internal/integrations/http_helpers.go

@@ -0,0 +1,31 @@
+package integrations
+
+import (
+	"bytes"
+	"io"
+	"net/http"
+)
+
+func StreamToString(stream io.Reader) string {
+	if stream == nil {
+		return ""
+	}
+	buf := new(bytes.Buffer)
+	_, err := buf.ReadFrom(stream)
+	if err != nil {
+		return ""
+	}
+	return buf.String()
+}
+
+func CloneBody(r *http.Request) ([]byte, error) {
+	buf, _ := io.ReadAll(r.Body)
+	rdr1 := io.NopCloser(bytes.NewBuffer(buf))
+	rdr2 := io.NopCloser(bytes.NewBuffer(buf))
+	r.Body = rdr2 // OK since rdr2 implements the io.ReadCloser interface
+
+	defer rdr1.Close()
+	cloneBody, err := io.ReadAll(rdr2)
+
+	return cloneBody, err
+}