From 306512bf9c7f89f8d564616196682c4f313557b5 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Maximilian=20Pa=C3=9F?=
 <22845248+mpass99@users.noreply.github.com>
Date: Mon, 21 Aug 2023 13:21:48 +0200
Subject: [PATCH] Fix Context Values are not logged.

Only the Sentry hook uses the values of the passed context. Therefore, we removed the values from our log statements when we shifted them from an extra `WithField` call to the context.
We fix this behavior by introducing a Logrus Hook that copies a fixed set of context values to the logging data.
---
 internal/runner/nomad_runner.go |  2 +-
 pkg/dto/dto.go                  |  8 +++++--
 pkg/logging/context_hook.go     | 41 +++++++++++++++++++++++++++++++++
 pkg/logging/logging.go          |  1 +
 pkg/logging/sentry_hook.go      |  4 +---
 5 files changed, 50 insertions(+), 6 deletions(-)
 create mode 100644 pkg/logging/context_hook.go

diff --git a/internal/runner/nomad_runner.go b/internal/runner/nomad_runner.go
index f2161cf..02c03ab 100644
--- a/internal/runner/nomad_runner.go
+++ b/internal/runner/nomad_runner.go
@@ -26,7 +26,7 @@ const (
 	// runnerContextKey is the key used to store runners in context.Context.
 	runnerContextKey dto.ContextKey = "runner"
 	// destroyReasonContextKey is the key used to store the reason of the destruction in the context.Context.
-	destroyReasonContextKey dto.ContextKey = "destroyReason"
+	destroyReasonContextKey dto.ContextKey = dto.KeyRunnerDestroyReason
 	// SIGQUIT is the character that causes a tty to send the SIGQUIT signal to the controlled process.
 	SIGQUIT = 0x1c
 	// executionTimeoutGracePeriod is the time to wait after sending a SIGQUIT signal to a timed out execution.
diff --git a/pkg/dto/dto.go b/pkg/dto/dto.go
index 2c20852..f57def9 100644
--- a/pkg/dto/dto.go
+++ b/pkg/dto/dto.go
@@ -194,10 +194,14 @@ type ContextKey string
 
 // Keys to reference information (for logging or monitoring).
 const (
-	KeyRunnerID      = "runner_id"
-	KeyEnvironmentID = "environment_id"
+	KeyRunnerID            = "runner_id"
+	KeyEnvironmentID       = "environment_id"
+	KeyRunnerDestroyReason = "destroy_reason"
 )
 
+// LoggedContextKeys defines which keys will be logged if a context is passed to logrus. See ContextHook.
+var LoggedContextKeys = []ContextKey{KeyRunnerID, KeyEnvironmentID, KeyRunnerDestroyReason}
+
 // WebSocketMessageType is the type for the messages from Poseidon to the client.
 type WebSocketMessageType string
 
diff --git a/pkg/logging/context_hook.go b/pkg/logging/context_hook.go
new file mode 100644
index 0000000..bbd6a96
--- /dev/null
+++ b/pkg/logging/context_hook.go
@@ -0,0 +1,41 @@
+package logging
+
+import (
+	"github.com/openHPI/poseidon/pkg/dto"
+	"github.com/sirupsen/logrus"
+)
+
+// ContextHook logs the values referenced by the of dto.LoggedContextKeys.
+// By default Logrus does not log the values stored in the passed context.
+type ContextHook struct{}
+
+// Fire is triggered on new log entries.
+func (hook *ContextHook) Fire(entry *logrus.Entry) error {
+	if entry.Context != nil {
+		injectContextValuesIntoData(entry)
+	}
+	return nil
+}
+
+func injectContextValuesIntoData(entry *logrus.Entry) {
+	for _, key := range dto.LoggedContextKeys {
+		value := entry.Context.Value(key)
+		_, valueExisting := entry.Data[string(key)]
+		if !valueExisting && value != nil {
+			entry.Data[string(key)] = value
+		}
+	}
+}
+
+// Levels returns all levels this hook should be registered to.
+func (hook *ContextHook) Levels() []logrus.Level {
+	return []logrus.Level{
+		logrus.PanicLevel,
+		logrus.FatalLevel,
+		logrus.ErrorLevel,
+		logrus.WarnLevel,
+		logrus.InfoLevel,
+		logrus.DebugLevel,
+		logrus.TraceLevel,
+	}
+}
diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go
index e985512..c7e0ab1 100644
--- a/pkg/logging/logging.go
+++ b/pkg/logging/logging.go
@@ -40,6 +40,7 @@ func InitializeLogging(logLevel string, formatter dto.Formatter) {
 			TimestampFormat: TimestampFormat,
 		}
 	}
+	log.AddHook(&ContextHook{})
 	log.AddHook(&SentryHook{})
 	log.ExitFunc = func(i int) {
 		sentry.Flush(GracefulSentryShutdown)
diff --git a/pkg/logging/sentry_hook.go b/pkg/logging/sentry_hook.go
index 1749bd9..315dc53 100644
--- a/pkg/logging/sentry_hook.go
+++ b/pkg/logging/sentry_hook.go
@@ -19,9 +19,7 @@ func (hook *SentryHook) Fire(entry *logrus.Entry) error {
 	var hub *sentry.Hub
 	if entry.Context != nil {
 		hub = sentry.GetHubFromContext(entry.Context)
-		// This might overwrite valid data when not the request context is passed.
-		entry.Data[dto.KeyRunnerID] = entry.Context.Value(dto.ContextKey(dto.KeyRunnerID))
-		entry.Data[dto.KeyEnvironmentID] = entry.Context.Value(dto.ContextKey(dto.KeyEnvironmentID))
+		injectContextValuesIntoData(entry)
 	}
 	if hub == nil {
 		hub = sentry.CurrentHub()