From d3071146da67aa67dc7abd6605e6415bbd22d750 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Sybren=20A=2E=20St=C3=BCvel?= <sybren@blender.org>
Date: Mon, 31 Jan 2022 15:35:57 +0100
Subject: [PATCH] Better logging of worker info

---
 cmd/flamenco-manager-poc/main.go         |  1 -
 internal/manager/api_impl/logging.go     | 31 ++++++------------------
 internal/manager/api_impl/worker_auth.go | 11 +++++++++
 internal/manager/api_impl/workers.go     |  7 ++++--
 4 files changed, 24 insertions(+), 26 deletions(-)

diff --git a/cmd/flamenco-manager-poc/main.go b/cmd/flamenco-manager-poc/main.go
index d6e1275c..de77be42 100644
--- a/cmd/flamenco-manager-poc/main.go
+++ b/cmd/flamenco-manager-poc/main.go
@@ -89,7 +89,6 @@ func buildWebService(flamenco api.ServerInterface, persist api_impl.PersistenceS
 
 	// Ensure panics when serving a web request won't bring down the server.
 	e.Use(middleware.Recover())
-	e.Use(api_impl.MiddleWareRequestLogger)
 
 	// Load the API definition and enable validation & authentication checks.
 	swagger, err := api.GetSwagger()
diff --git a/internal/manager/api_impl/logging.go b/internal/manager/api_impl/logging.go
index 0e59d8cd..a809b44f 100644
--- a/internal/manager/api_impl/logging.go
+++ b/internal/manager/api_impl/logging.go
@@ -21,8 +21,6 @@ package api_impl
  * ***** END GPL LICENSE BLOCK ***** */
 
 import (
-	"context"
-
 	"github.com/labstack/echo/v4"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
@@ -34,28 +32,15 @@ const (
 	loggerKey = loggerContextKey("logger")
 )
 
-// MiddleWareRequestLogger is Echo middleware that puts a Zerolog logger in the request context, for endpoints to use.
-func MiddleWareRequestLogger(next echo.HandlerFunc) echo.HandlerFunc {
-	return func(c echo.Context) error {
-		remoteIP := c.RealIP()
-		logger := log.With().Str("remoteAddr", remoteIP).Logger()
-		ctx := context.WithValue(c.Request().Context(), loggerKey, logger)
-		c.SetRequest(c.Request().WithContext(ctx))
-
-		if err := next(c); err != nil {
-			c.Error(err)
-		}
-		return nil
-	}
-}
-
 func requestLogger(e echo.Context) zerolog.Logger {
-	ctx := e.Request().Context()
-	logger, ok := ctx.Value(loggerKey).(zerolog.Logger)
-	if ok {
-		return logger
+	logCtx := log.With().Str("remoteAddr", e.RealIP())
+
+	worker := requestWorker(e)
+	if worker != nil {
+		logCtx = logCtx.
+			Str("wUUID", worker.UUID).
+			Str("wName", worker.Name)
 	}
 
-	log.Error().Msg("no logger found in request context, returning default logger")
-	return log.With().Logger()
+	return logCtx.Logger()
 }
diff --git a/internal/manager/api_impl/worker_auth.go b/internal/manager/api_impl/worker_auth.go
index 54a5375a..2027aeb3 100644
--- a/internal/manager/api_impl/worker_auth.go
+++ b/internal/manager/api_impl/worker_auth.go
@@ -27,6 +27,7 @@ import (
 	oapi_middle "github.com/deepmap/oapi-codegen/pkg/middleware"
 	"github.com/getkin/kin-openapi/openapi3filter"
 	"github.com/labstack/echo/v4"
+	"gitlab.com/blender/flamenco-ng-poc/internal/manager/persistence"
 	"golang.org/x/crypto/bcrypt"
 )
 
@@ -77,3 +78,13 @@ func WorkerAuth(ctx context.Context, authInfo *openapi3filter.AuthenticationInpu
 
 	return nil
 }
+
+// requestWorker returns the Worker associated with this HTTP request.
+func requestWorker(e echo.Context) *persistence.Worker {
+	ctx := e.Request().Context()
+	worker, ok := ctx.Value(workerKey).(*persistence.Worker)
+	if ok {
+		return worker
+	}
+	return nil
+}
diff --git a/internal/manager/api_impl/workers.go b/internal/manager/api_impl/workers.go
index e11cbfcc..fdb8bd18 100644
--- a/internal/manager/api_impl/workers.go
+++ b/internal/manager/api_impl/workers.go
@@ -88,7 +88,7 @@ func (f *Flamenco) SignOn(e echo.Context) error {
 		return sendAPIError(e, http.StatusBadRequest, "invalid format")
 	}
 
-	logger.Info().Str("nickname", req.Nickname).Msg("worker signing on")
+	logger.Info().Msg("worker signing on")
 
 	return e.JSON(http.StatusOK, &api.WorkerStateChange{
 		// TODO: look up proper status in DB.
@@ -106,7 +106,7 @@ func (f *Flamenco) SignOff(e echo.Context) error {
 		return sendAPIError(e, http.StatusBadRequest, "invalid format")
 	}
 
-	logger.Info().Str("nickname", req.Nickname).Msg("worker signing off")
+	logger.Info().Msg("worker signing off")
 
 	// TODO: store status in DB.
 	return e.String(http.StatusNoContent, "")
@@ -135,6 +135,9 @@ func (f *Flamenco) WorkerStateChanged(e echo.Context) error {
 }
 
 func (f *Flamenco) ScheduleTask(e echo.Context) error {
+	logger := requestLogger(e)
+	logger.Info().Msg("worker requesting task")
+
 	return e.JSON(http.StatusOK, &api.AssignedTask{
 		Uuid: uuid.New().String(),
 		Commands: []api.Command{