diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index ef52d19..4383fed 100644 --- a/.github/workflows/ci.yml +++ b/.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 diff --git a/cmd/poseidon/main.go b/cmd/poseidon/main.go index d8b3049..4389033 100644 --- a/cmd/poseidon/main.go +++ b/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) diff --git a/internal/config/config.go b/internal/config/config.go index 876211c..14ef176 100644 --- a/internal/config/config.go +++ b/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{ - Level: "INFO", + Logger: Logger{ + Level: "INFO", + Formatter: dto.FormatterText, }, Sentry: sentry.ClientOptions{ AttachStacktrace: true, @@ -120,9 +122,10 @@ type TLS struct { KeyFile string } -// logger configures the used logger. -type logger struct { - Level string +// Logger configures the used Logger. +type Logger struct { + 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 diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 24c8623..b17ae23 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -33,7 +33,7 @@ func newTestConfiguration() *configuration { Active: false, }, }, - Logger: logger{ + Logger: Logger{ Level: "INFO", }, } diff --git a/pkg/dto/dto.go b/pkg/dto/dto.go index b94cc44..2c20852 100644 --- a/pkg/dto/dto.go +++ b/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 diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 673d6f1..e985512 100644 --- a/pkg/logging/logging.go +++ b/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) { - level, err := logrus.ParseLevel(loglevel) +func InitializeLogging(logLevel string, formatter dto.Formatter) { + 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 { - return &loggingResponseWriter{w, http.StatusOK} +func NewLoggingResponseWriter(w http.ResponseWriter) *ResponseWriter { + 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) diff --git a/pkg/logging/logging_test.go b/pkg/logging/logging_test.go index b21277a..7b2c7c6 100644 --- a/pkg/logging/logging_test.go +++ b/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 { diff --git a/tests/e2e/websocket_test.go b/tests/e2e/websocket_test.go index 1ccb6b1..e2592f2 100644 --- a/tests/e2e/websocket_test.go +++ b/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)