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

@@ -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.

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
 

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,
+	}
+}

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)

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()