Add regression e2e test for incomplete debug message.

See #325.

.github/workflows/ci.yml

@@ -127,6 +127,8 @@ jobs:
       POSEIDON_AWS_ENABLED: false
       POSEIDON_AWS_ENDPOINT: ${{ secrets.POSEIDON_AWS_ENDPOINT }}
       POSEIDON_AWS_FUNCTIONS: ""
+      POSEIDON_LOGGER_FORMATTER: "JSONFormatter"
+      POSEIDON_LOG_FILE: "../../poseidon.log"
       POSEIDON_NOMAD_DISABLEFORCEPULL: true
       GOCOVERDIR: coverage
     steps:
@@ -204,7 +206,7 @@ jobs:
           until curl -s --fail http://localhost:4646/v1/agent/health ; do sleep 1; done
           chmod +x ./poseidon
           mkdir -p ${GOCOVERDIR}
-          ./poseidon &
+          ./poseidon | tee poseidon.log &
           until curl -s --fail http://localhost:7200/api/v1/health ; do sleep 1; done
           make e2e-test
       - name: Run e2e recovery tests

cmd/poseidon/main.go

@@ -230,7 +230,7 @@ func main() {
 	if err := config.InitConfig(); err != nil {
 		log.WithError(err).Warn("Could not initialize configuration")
 	}
-	logging.InitializeLogging(config.Config.Logger.Level)
+	logging.InitializeLogging(config.Config.Logger.Level, config.Config.Logger.Formatter)
 	initSentry(&config.Config.Sentry, config.Config.Profiling.Enabled)
 
 	cancelInflux := monitoring.InitializeInfluxDB(&config.Config.InfluxDB)

internal/config/config.go

@@ -6,6 +6,7 @@ import (
 	"flag"
 	"fmt"
 	"github.com/getsentry/sentry-go"
+	"github.com/openHPI/poseidon/pkg/dto"
 	"github.com/openHPI/poseidon/pkg/logging"
 	"github.com/sirupsen/logrus"
 	"gopkg.in/yaml.v3"
@@ -50,8 +51,9 @@ var (
 			Endpoint:  "",
 			Functions: []string{},
 		},
-		Logger: logger{
+		Logger: Logger{
-			Level: "INFO",
+			Level:     "INFO",
+			Formatter: dto.FormatterText,
 		},
 		Sentry: sentry.ClientOptions{
 			AttachStacktrace: true,
@@ -120,9 +122,10 @@ type TLS struct {
 	KeyFile  string
 }
 
-// logger configures the used logger.
+// Logger configures the used Logger.
-type logger struct {
+type Logger struct {
-	Level string
+	Formatter dto.Formatter
+	Level     string
 }
 
 // Profiling configures the usage of a runtime profiler to create optimized binaries.
@@ -145,7 +148,7 @@ type configuration struct {
 	Server    server
 	Nomad     Nomad
 	AWS       AWS
-	Logger    logger
+	Logger    Logger
 	Profiling Profiling
 	Sentry    sentry.ClientOptions
 	InfluxDB  InfluxDB

internal/config/config_test.go

@@ -33,7 +33,7 @@ func newTestConfiguration() *configuration {
 				Active: false,
 			},
 		},
-		Logger: logger{
+		Logger: Logger{
 			Level: "INFO",
 		},
 	}

pkg/dto/dto.go

@@ -181,6 +181,14 @@ func (f File) ByteContent() []byte {
 	}
 }
 
+// Formatter mirrors the available Formatters of logrus for configuration purposes.
+type Formatter string
+
+const (
+	FormatterText = "TextFormatter"
+	FormatterJSON = "JSONFormatter"
+)
+
 // ContextKey is the type for keys in a request context that is used for passing data to the next handler.
 type ContextKey string
 

pkg/logging/logging.go

@@ -4,6 +4,7 @@ import (
 	"bufio"
 	"fmt"
 	"github.com/getsentry/sentry-go"
+	"github.com/openHPI/poseidon/pkg/dto"
 	"github.com/sirupsen/logrus"
 	"net"
 	"net/http"
@@ -12,10 +13,12 @@ import (
 	"time"
 )
 
+const TimestampFormat = "2006-01-02T15:04:05.000000Z"
+
 var log = &logrus.Logger{
 	Out: os.Stderr,
 	Formatter: &logrus.TextFormatter{
-		TimestampFormat: "2006-01-02T15:04:05.000000Z",
+		TimestampFormat: TimestampFormat,
 		DisableColors:   true,
 		FullTimestamp:   true,
 	},
@@ -25,13 +28,18 @@ var log = &logrus.Logger{
 
 const GracefulSentryShutdown = 5 * time.Second
 
-func InitializeLogging(loglevel string) {
+func InitializeLogging(logLevel string, formatter dto.Formatter) {
-	level, err := logrus.ParseLevel(loglevel)
+	level, err := logrus.ParseLevel(logLevel)
 	if err != nil {
 		log.WithError(err).Fatal("Error parsing loglevel")
 		return
 	}
 	log.SetLevel(level)
+	if formatter == dto.FormatterJSON {
+		log.Formatter = &logrus.JSONFormatter{
+			TimestampFormat: TimestampFormat,
+		}
+	}
 	log.AddHook(&SentryHook{})
 	log.ExitFunc = func(i int) {
 		sentry.Flush(GracefulSentryShutdown)
@@ -43,23 +51,23 @@ func GetLogger(pkg string) *logrus.Entry {
 	return log.WithField("package", pkg)
 }
 
-// loggingResponseWriter wraps the default http.ResponseWriter and catches the status code
+// ResponseWriter wraps the default http.ResponseWriter and catches the status code
 // that is written.
-type loggingResponseWriter struct {
+type ResponseWriter struct {
 	http.ResponseWriter
 	StatusCode int
 }
 
-func NewLoggingResponseWriter(w http.ResponseWriter) *loggingResponseWriter {
+func NewLoggingResponseWriter(w http.ResponseWriter) *ResponseWriter {
-	return &loggingResponseWriter{w, http.StatusOK}
+	return &ResponseWriter{w, http.StatusOK}
 }
 
-func (writer *loggingResponseWriter) WriteHeader(code int) {
+func (writer *ResponseWriter) WriteHeader(code int) {
 	writer.StatusCode = code
 	writer.ResponseWriter.WriteHeader(code)
 }
 
-func (writer *loggingResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+func (writer *ResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
 	conn, rw, err := writer.ResponseWriter.(http.Hijacker).Hijack()
 	if err != nil {
 		return conn, nil, fmt.Errorf("hijacking connection failed: %w", err)

pkg/logging/logging_test.go

@@ -1,6 +1,7 @@
 package logging
 
 import (
+	"github.com/openHPI/poseidon/pkg/dto"
 	"github.com/sirupsen/logrus"
 	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
@@ -18,7 +19,7 @@ func mockHTTPStatusHandler(status int) http.Handler {
 func TestHTTPMiddlewareWarnsWhenInternalServerError(t *testing.T) {
 	var hook *test.Hook
 	log, hook = test.NewNullLogger()
-	InitializeLogging(logrus.DebugLevel.String())
+	InitializeLogging(logrus.DebugLevel.String(), dto.FormatterText)
 
 	request, err := http.NewRequest(http.MethodGet, "/", http.NoBody)
 	if err != nil {
@@ -34,7 +35,7 @@ func TestHTTPMiddlewareWarnsWhenInternalServerError(t *testing.T) {
 func TestHTTPMiddlewareDebugsWhenStatusOK(t *testing.T) {
 	var hook *test.Hook
 	log, hook = test.NewNullLogger()
-	InitializeLogging(logrus.DebugLevel.String())
+	InitializeLogging(logrus.DebugLevel.String(), dto.FormatterText)
 
 	request, err := http.NewRequest(http.MethodGet, "/", http.NoBody)
 	if err != nil {

tests/e2e/websocket_test.go

@@ -1,22 +1,33 @@
 package e2e
 
 import (
+	"bufio"
 	"bytes"
 	"context"
+	"encoding/json"
 	"fmt"
 	"github.com/gorilla/websocket"
 	"github.com/openHPI/poseidon/internal/nomad"
 	"github.com/openHPI/poseidon/pkg/dto"
+	"github.com/openHPI/poseidon/pkg/logging"
 	"github.com/openHPI/poseidon/tests"
 	"github.com/openHPI/poseidon/tests/helpers"
+	"github.com/stretchr/testify/require"
 	"github.com/stretchr/testify/suite"
 	"net/http"
+	"os"
 	"regexp"
 	"strconv"
 	"strings"
+	"testing"
 	"time"
 )
 
+const (
+	EnvPoseidonLogFile      = "POSEIDON_LOG_FILE"
+	EnvPoseidonLogFormatter = "POSEIDON_LOGGER_FORMATTER"
+)
+
 func (s *E2ETestSuite) TestExecuteCommandRoute() {
 	for _, environmentID := range environmentIDs {
 		s.Run(environmentID.ToString(), func() {
@@ -235,6 +246,81 @@ func (s *E2ETestSuite) TestNomadStderrFifoIsRemoved() {
 	s.NotContains(s.ListTempDirectory(runnerID), ".fifo", "/tmp/ should not contain any .fifo files after the execution")
 }
 
+func (s *E2ETestSuite) TestTerminatedByClient() {
+	logFile, logFileOk := os.LookupEnv(EnvPoseidonLogFile)
+	logFormatter, logFormatterOk := os.LookupEnv(EnvPoseidonLogFormatter)
+	if !logFileOk || !logFormatterOk || logFormatter != dto.FormatterJSON {
+		s.T().Skipf("The environment variables %s and %s are not set", EnvPoseidonLogFile, EnvPoseidonLogFormatter)
+		return
+	}
+	start := time.Now()
+
+	// The bug of #325 is triggered in about every second execution. Therefore, we perform
+	// 10 executions to have a high probability of triggering this (fixed) behavior.
+	const runs = 10
+	for i := 0; i < runs; i++ {
+		<-time.After(time.Duration(i) * time.Second)
+		log.WithField("i", i).Info("Run")
+		runnerID, err := ProvideRunner(&dto.RunnerRequest{
+			ExecutionEnvironmentID: tests.DefaultEnvironmentIDAsInteger,
+		})
+		s.Require().NoError(err)
+
+		webSocketURL, err := ProvideWebSocketURL(runnerID, &dto.ExecutionRequest{Command: "sleep 2"})
+		s.Require().NoError(err)
+		connection, err := ConnectToWebSocket(webSocketURL)
+		s.Require().NoError(err)
+
+		go func() {
+			<-time.After(time.Millisecond)
+			err := connection.WriteControl(websocket.CloseMessage,
+				websocket.FormatCloseMessage(websocket.CloseNormalClosure, ""), time.Now().Add(time.Second))
+			s.Require().NoError(err)
+			err = connection.Close()
+			s.Require().NoError(err)
+		}()
+
+		_, err = helpers.ReceiveAllWebSocketMessages(connection)
+		s.Require().Error(err)
+	}
+
+	records := parseLogFile(s.T(), logFile, start, time.Now())
+	for _, record := range records {
+		msg, ok := record["msg"].(string)
+		if !ok || msg == "Exec debug message could not be read completely" {
+			s.Failf("Found Error", "Ok: %t, message: %s", ok, msg)
+		}
+	}
+}
+
+func parseLogFile(t *testing.T, name string, start time.Time, end time.Time) (logRecords []map[string]interface{}) {
+	t.Helper()
+	<-time.After(tests.ShortTimeout)
+	file, err := os.Open(name)
+	require.NoError(t, err)
+	defer func(t *testing.T, file *os.File) {
+		t.Helper()
+		err := file.Close()
+		require.NoError(t, err)
+	}(t, file)
+	fileScanner := bufio.NewScanner(file)
+	fileScanner.Split(bufio.ScanLines)
+	for fileScanner.Scan() {
+		logRecord := map[string]interface{}{}
+		err = json.Unmarshal(fileScanner.Bytes(), &logRecord)
+		require.NoError(t, err)
+		timeString, ok := logRecord["time"].(string)
+		require.True(t, ok)
+		entryTime, err := time.ParseInLocation(logging.TimestampFormat, timeString, start.Location())
+		require.NoError(t, err)
+		if entryTime.Before(start) || entryTime.After(end) {
+			continue
+		}
+		logRecords = append(logRecords, logRecord)
+	}
+	return logRecords
+}
+
 func (s *E2ETestSuite) ListTempDirectory(runnerID string) string {
 	allocListStub, _, err := nomadClient.Jobs().Allocations(runnerID, true, nil)
 	s.Require().NoError(err)