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

@@ -7,6 +7,7 @@ DEV_MODE ?= false
 DEV_MODE_PORT ?= 8080
 # 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
@@ -47,7 +48,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) --mock-k8s-client=$(MOCK_K8S_CLIENT) --mock-mr-client=$(MOCK_MR_CLIENT) --dev-mode=$(DEV_MODE) --dev-mode-port=$(DEV_MODE_PORT)
+	go run ./cmd/main.go  --port=$(PORT) --mock-k8s-client=$(MOCK_K8S_CLIENT) --mock-mr-client=$(MOCK_MR_CLIENT) --dev-mode=$(DEV_MODE) --dev-mode-port=$(DEV_MODE_PORT) --log-level=$(LOG_LEVEL)
 
 .PHONY: docker-build
 docker-build: ## Builds a container for the project.

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"
@@ -24,9 +25,12 @@ func main() {
 	flag.BoolVar(&cfg.MockMRClient, "mock-mr-client", false, "Use mock Model Registry client")
 	flag.BoolVar(&cfg.DevMode, "dev-mode", false, "Use development mode for access to local K8s cluster")
 	flag.IntVar(&cfg.DevModePort, "dev-mode-port", getEnvAsInt("DEV_MODE_PORT", 8080), "Use port when in development mode")
+	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 {
@@ -86,3 +90,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

@@ -106,5 +106,5 @@ func (app *App) Routes() http.Handler {
 	router.GET(ModelRegistryListPath, app.ModelRegistryHandler)
 	router.PATCH(ModelRegistryPath, app.AttachRESTClient(app.UpdateModelVersionHandler))
 
-	return app.RecoverPanic(app.enableCORS(router))
+	return app.RecoverPanic(app.InitializeContext(app.enableCORS(router)))
 }

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

@@ -5,13 +5,16 @@ import (
 	"fmt"
 	"net/http"
 
+	"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"
 )
 
 type contextKey string
 
+const traceIdKey contextKey = "traceIdKey"
 const httpClientKey contextKey = "httpClientKey"
 const userAccessToken = "x-forwarded-access-token"
 
@@ -38,6 +41,15 @@ func (app *App) enableCORS(next http.Handler) http.Handler {
 	})
 }
 
+func (app *App) InitializeContext(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
+		ctx := context.WithValue(r.Context(), traceIdKey, uuid.NewString())
+
+		next.ServeHTTP(w, r.WithContext(ctx))
+	})
+}
+
 func (app *App) AttachRESTClient(handler func(http.ResponseWriter, *http.Request, httprouter.Params)) httprouter.Handle {
 	return func(w http.ResponseWriter, r *http.Request, ps httprouter.Params) {
 
@@ -55,7 +67,19 @@ func (app *App) AttachRESTClient(handler func(http.ResponseWriter, *http.Request
 			return
 		}
 
-		client, err := integrations.NewHTTPClient(modelRegistryBaseURL, bearerToken)
+		// 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(modelRegistryBaseURL, bearerToken, restClientLogger)
 		if err != nil {
 			app.serverErrorResponse(w, r, fmt.Errorf("failed to create Kubernetes client: %v", err))
 			return

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

@@ -6,4 +6,5 @@ type EnvConfig struct {
 	MockMRClient bool
 	DevMode      bool
 	DevModePort  int
+	LogLevel     string
 }

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

@@ -1,10 +1,13 @@
 package integrations
 
 import (
+	"bytes"
 	"crypto/tls"
 	"encoding/json"
 	"fmt"
+	"github.com/google/uuid"
 	"io"
+	"log/slog"
 	"net/http"
 	"strconv"
 )
@@ -19,6 +22,7 @@ type HTTPClient struct {
 	client      *http.Client
 	baseURL     string
 	bearerToken string
+	logger      *slog.Logger
 }
 
 type ErrorResponse struct {
@@ -35,39 +39,50 @@ func (e *HTTPError) Error() string {
 	return fmt.Sprintf("HTTP %d: %s - %s", e.StatusCode, e.Code, e.Message)
 }
 
-func NewHTTPClient(baseURL string, bearerToken string) (HTTPClientInterface, error) {
+func NewHTTPClient(baseURL string, bearerToken string, logger *slog.Logger) (HTTPClientInterface, error) {
 
 	return &HTTPClient{
 		client: &http.Client{Transport: &http.Transport{
 			TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
 		}},
 		baseURL:     baseURL,
 		bearerToken: bearerToken,
+		logger:      logger,
 	}, nil
 }
 
 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
 	}
 
 	req.Header.Add("Authorization", "Bearer "+c.bearerToken)
+
+	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)
@@ -78,13 +93,17 @@ func (c *HTTPClient) POST(url string, body io.Reader) ([]byte, error) {
 	req.Header.Set("Content-Type", "application/json")
 	req.Header.Add("Authorization", "Bearer "+c.bearerToken)
 
+	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)
 	}
@@ -117,16 +136,21 @@ func (c *HTTPClient) PATCH(url string, body io.Reader) ([]byte, error) {
 		return nil, err
 	}
 
+	requestId := uuid.NewString()
+
 	req.Header.Set("Content-Type", "application/json")
 	req.Header.Add("Authorization", "Bearer "+c.bearerToken)
 
+	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)
 	}
@@ -150,3 +174,31 @@ 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(nil, 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(nil, slog.LevelDebug) {
+		logger.Debug("Received upstream HTTP response", "request_id", reqId, "status_code", resp.StatusCode, "body", body)
+	}
+}
+
+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()
+}