Add context to log statements.

This commit is contained in:
Maximilian Paß
2023-04-11 19:24:06 +01:00
parent 43221c717e
commit 0c8fa9ccfa
16 changed files with 97 additions and 88 deletions

View File

@ -42,7 +42,7 @@ func NewRouter(runnerManager runner.Manager, environmentManager environment.Mana
func configureV1Router(router *mux.Router,
runnerManager runner.Manager, environmentManager environment.ManagerHandler) {
router.NotFoundHandler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
log.WithField("request", r).Debug("Not Found Handler")
log.WithContext(r.Context()).WithField("request", r).Debug("Not Found Handler")
w.WriteHeader(http.StatusNotFound)
})
v1 := router.PathPrefix(BasePath).Subrouter()
@ -75,10 +75,10 @@ func configureV1Router(router *mux.Router,
// Version handles the version route.
// It responds the release information stored in the configuration.
func Version(writer http.ResponseWriter, _ *http.Request) {
func Version(writer http.ResponseWriter, request *http.Request) {
release := config.Config.Sentry.Release
if len(release) > 0 {
sendJSON(writer, release, http.StatusOK)
sendJSON(writer, release, http.StatusOK, request.Context())
} else {
writer.WriteHeader(http.StatusNotFound)
}
@ -87,12 +87,12 @@ func Version(writer http.ResponseWriter, _ *http.Request) {
// StatisticsExecutionEnvironments handles the route for statistics about execution environments.
// It responds the prewarming pool size and the number of idle runners and used runners.
func StatisticsExecutionEnvironments(manager environment.Manager) http.HandlerFunc {
return func(writer http.ResponseWriter, _ *http.Request) {
return func(writer http.ResponseWriter, request *http.Request) {
result := make(map[string]*dto.StatisticalExecutionEnvironmentData)
environmentsData := manager.Statistics()
for id, data := range environmentsData {
result[id.ToString()] = data
}
sendJSON(writer, result, http.StatusOK)
sendJSON(writer, result, http.StatusOK, request.Context())
}
}

View File

@ -27,7 +27,8 @@ func HTTPAuthenticationMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
token := r.Header.Get(TokenHeader)
if subtle.ConstantTimeCompare([]byte(token), correctAuthenticationToken) == 0 {
log.WithField("token", logging.RemoveNewlineSymbol(token)).
log.WithContext(r.Context()).
WithField("token", logging.RemoveNewlineSymbol(token)).
Warn("Incorrect token")
w.WriteHeader(http.StatusUnauthorized)
return

View File

@ -47,17 +47,17 @@ func (e *EnvironmentController) ConfigureRoutes(router *mux.Router) {
func (e *EnvironmentController) list(writer http.ResponseWriter, request *http.Request) {
fetch, err := parseFetchParameter(request)
if err != nil {
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return
}
environments, err := e.manager.List(fetch)
if err != nil {
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
sendJSON(writer, ExecutionEnvironmentsResponse{environments}, http.StatusOK)
sendJSON(writer, ExecutionEnvironmentsResponse{environments}, http.StatusOK, request.Context())
}
// get returns all information about the requested execution environment.
@ -65,12 +65,12 @@ func (e *EnvironmentController) get(writer http.ResponseWriter, request *http.Re
environmentID, err := parseEnvironmentID(request)
if err != nil {
// This case is never used as the router validates the id format
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return
}
fetch, err := parseFetchParameter(request)
if err != nil {
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return
}
@ -79,11 +79,11 @@ func (e *EnvironmentController) get(writer http.ResponseWriter, request *http.Re
writer.WriteHeader(http.StatusNotFound)
return
} else if err != nil {
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
sendJSON(writer, executionEnvironment, http.StatusOK)
sendJSON(writer, executionEnvironment, http.StatusOK, request.Context())
}
// delete removes the specified execution environment.
@ -91,13 +91,13 @@ func (e *EnvironmentController) delete(writer http.ResponseWriter, request *http
environmentID, err := parseEnvironmentID(request)
if err != nil {
// This case is never used as the router validates the id format
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return
}
found, err := e.manager.Delete(environmentID)
if err != nil {
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
} else if !found {
writer.WriteHeader(http.StatusNotFound)
@ -111,12 +111,12 @@ func (e *EnvironmentController) delete(writer http.ResponseWriter, request *http
func (e *EnvironmentController) createOrUpdate(writer http.ResponseWriter, request *http.Request) {
req := new(dto.ExecutionEnvironmentRequest)
if err := json.NewDecoder(request.Body).Decode(req); err != nil {
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return
}
environmentID, err := parseEnvironmentID(request)
if err != nil {
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return
}
@ -125,7 +125,7 @@ func (e *EnvironmentController) createOrUpdate(writer http.ResponseWriter, reque
created, err = e.manager.CreateOrUpdate(environmentID, *req, ctx)
})
if err != nil {
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
}
if created {

View File

@ -1,38 +1,40 @@
package api
import (
"context"
"encoding/json"
"fmt"
"github.com/openHPI/poseidon/pkg/dto"
"net/http"
)
func writeInternalServerError(writer http.ResponseWriter, err error, errorCode dto.ErrorCode) {
sendJSON(writer, &dto.InternalServerError{Message: err.Error(), ErrorCode: errorCode}, http.StatusInternalServerError)
func writeInternalServerError(writer http.ResponseWriter, err error, errorCode dto.ErrorCode, ctx context.Context) {
sendJSON(writer, &dto.InternalServerError{Message: err.Error(), ErrorCode: errorCode},
http.StatusInternalServerError, ctx)
}
func writeClientError(writer http.ResponseWriter, err error, status uint16) {
sendJSON(writer, &dto.ClientError{Message: err.Error()}, int(status))
func writeClientError(writer http.ResponseWriter, err error, status uint16, ctx context.Context) {
sendJSON(writer, &dto.ClientError{Message: err.Error()}, int(status), ctx)
}
func sendJSON(writer http.ResponseWriter, content interface{}, httpStatusCode int) {
func sendJSON(writer http.ResponseWriter, content interface{}, httpStatusCode int, ctx context.Context) {
writer.Header().Set("Content-Type", "application/json")
writer.WriteHeader(httpStatusCode)
response, err := json.Marshal(content)
if err != nil {
// cannot produce infinite recursive loop, since json.Marshal of dto.InternalServerError won't return an error
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, ctx)
return
}
if _, err = writer.Write(response); err != nil {
log.WithError(err).Error("Could not write JSON response")
log.WithError(err).WithContext(ctx).Error("Could not write JSON response")
http.Error(writer, err.Error(), http.StatusInternalServerError)
}
}
func parseJSONRequestBody(writer http.ResponseWriter, request *http.Request, structure interface{}) error {
if err := json.NewDecoder(request.Body).Decode(structure); err != nil {
writeClientError(writer, err, http.StatusBadRequest)
writeClientError(writer, err, http.StatusBadRequest, request.Context())
return fmt.Errorf("error parsing JSON request body: %w", err)
}
return nil

View File

@ -74,18 +74,20 @@ func (r *RunnerController) provide(writer http.ResponseWriter, request *http.Req
if err != nil {
switch {
case errors.Is(err, runner.ErrUnknownExecutionEnvironment):
writeClientError(writer, err, http.StatusNotFound)
writeClientError(writer, err, http.StatusNotFound, request.Context())
case errors.Is(err, runner.ErrNoRunnersAvailable):
log.WithField("environment", logging.RemoveNewlineSymbol(strconv.Itoa(int(environmentID)))).
log.WithContext(request.Context()).
WithField("environment", logging.RemoveNewlineSymbol(strconv.Itoa(int(environmentID)))).
Warn("No runners available")
writeInternalServerError(writer, err, dto.ErrorNomadOverload)
writeInternalServerError(writer, err, dto.ErrorNomadOverload, request.Context())
default:
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
}
return
}
monitoring.AddRunnerMonitoringData(request, nextRunner.ID(), nextRunner.Environment())
sendJSON(writer, &dto.RunnerResponse{ID: nextRunner.ID(), MappedPorts: nextRunner.MappedPorts()}, http.StatusOK)
sendJSON(writer, &dto.RunnerResponse{ID: nextRunner.ID(), MappedPorts: nextRunner.MappedPorts()},
http.StatusOK, request.Context())
}
// listFileSystem handles the files API route with the method GET.
@ -112,11 +114,11 @@ func (r *RunnerController) listFileSystem(writer http.ResponseWriter, request *h
err = targetRunner.ListFileSystem(path, recursive, writer, privilegedExecution, ctx)
})
if errors.Is(err, runner.ErrFileNotFound) {
writeClientError(writer, err, http.StatusFailedDependency)
writeClientError(writer, err, http.StatusFailedDependency, request.Context())
return
} else if err != nil {
log.WithError(err).Error("Could not perform the requested listFileSystem.")
writeInternalServerError(writer, err, dto.ErrorUnknown)
log.WithContext(request.Context()).WithError(err).Error("Could not perform the requested listFileSystem.")
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
}
@ -138,8 +140,8 @@ func (r *RunnerController) updateFileSystem(writer http.ResponseWriter, request
err = targetRunner.UpdateFileSystem(fileCopyRequest, ctx)
})
if err != nil {
log.WithError(err).Error("Could not perform the requested updateFileSystem.")
writeInternalServerError(writer, err, dto.ErrorUnknown)
log.WithContext(request.Context()).WithError(err).Error("Could not perform the requested updateFileSystem.")
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
@ -160,11 +162,11 @@ func (r *RunnerController) fileContent(writer http.ResponseWriter, request *http
err = targetRunner.GetFileContent(path, writer, privilegedExecution, ctx)
})
if errors.Is(err, runner.ErrFileNotFound) {
writeClientError(writer, err, http.StatusFailedDependency)
writeClientError(writer, err, http.StatusFailedDependency, request.Context())
return
} else if err != nil {
log.WithError(err).Error("Could not retrieve the requested file.")
writeInternalServerError(writer, err, dto.ErrorUnknown)
log.WithContext(request.Context()).WithError(err).Error("Could not retrieve the requested file.")
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
}
@ -179,7 +181,7 @@ func (r *RunnerController) execute(writer http.ResponseWriter, request *http.Req
}
forbiddenCharacters := "'"
if strings.ContainsAny(executionRequest.Command, forbiddenCharacters) {
writeClientError(writer, ErrForbiddenCharacter, http.StatusBadRequest)
writeClientError(writer, ErrForbiddenCharacter, http.StatusBadRequest, request.Context())
return
}
@ -194,14 +196,14 @@ func (r *RunnerController) execute(writer http.ResponseWriter, request *http.Req
path, err := r.runnerRouter.Get(WebsocketPath).URL(RunnerIDKey, targetRunner.ID())
if err != nil {
log.WithError(err).Error("Could not create runner websocket URL.")
writeInternalServerError(writer, err, dto.ErrorUnknown)
log.WithContext(request.Context()).WithError(err).Error("Could not create runner websocket URL.")
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
newUUID, err := uuid.NewRandom()
if err != nil {
log.WithError(err).Error("Could not create execution id")
writeInternalServerError(writer, err, dto.ErrorUnknown)
log.WithContext(request.Context()).WithError(err).Error("Could not create execution id")
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
id := newUUID.String()
@ -216,7 +218,7 @@ func (r *RunnerController) execute(writer http.ResponseWriter, request *http.Req
RawQuery: fmt.Sprintf("%s=%s", ExecutionIDKey, id),
}
sendJSON(writer, &dto.ExecutionResponse{WebSocketURL: webSocketURL.String()}, http.StatusOK)
sendJSON(writer, &dto.ExecutionResponse{WebSocketURL: webSocketURL.String()}, http.StatusOK, request.Context())
}
// The findRunnerMiddleware looks up the runnerId for routes containing it
@ -230,9 +232,9 @@ func (r *RunnerController) findRunnerMiddleware(next http.Handler) http.Handler
// See https://github.com/openHPI/poseidon/issues/54
_, readErr := io.ReadAll(request.Body)
if readErr != nil {
log.WithError(readErr).Warn("Failed to discard the request body")
log.WithContext(request.Context()).WithError(readErr).Warn("Failed to discard the request body")
}
writeClientError(writer, err, http.StatusGone)
writeClientError(writer, err, http.StatusGone, request.Context())
return
}
ctx := runner.NewContext(request.Context(), targetRunner)
@ -252,7 +254,7 @@ func (r *RunnerController) delete(writer http.ResponseWriter, request *http.Requ
err = r.manager.Return(targetRunner)
})
if err != nil {
writeInternalServerError(writer, err, dto.ErrorNomadInternalServerError)
writeInternalServerError(writer, err, dto.ErrorNomadInternalServerError, request.Context())
return
}

View File

@ -4,6 +4,7 @@ import (
"context"
"errors"
"fmt"
"github.com/getsentry/sentry-go"
"github.com/gorilla/websocket"
"github.com/openHPI/poseidon/internal/api/ws"
"github.com/openHPI/poseidon/internal/runner"
@ -28,7 +29,7 @@ func upgradeConnection(writer http.ResponseWriter, request *http.Request) (ws.Co
connUpgrader := websocket.Upgrader{}
connection, err := connUpgrader.Upgrade(writer, request, nil)
if err != nil {
log.WithError(err).Warn("Connection upgrade failed")
log.WithContext(request.Context()).WithError(err).Warn("Connection upgrade failed")
return nil, fmt.Errorf("error upgrading the connection: %w", err)
}
return connection, nil
@ -61,13 +62,13 @@ func (wp *webSocketProxy) waitForExit(exit <-chan runner.ExitInfo, cancelExecuti
var exitInfo runner.ExitInfo
select {
case <-wp.ctx.Done():
log.Info("Client closed the connection")
log.WithContext(wp.ctx).Info("Client closed the connection")
wp.Input.Stop()
cancelExecution()
<-exit // /internal/runner/runner.go handleExitOrContextDone does not require client connection anymore.
<-exit // The goroutine closes this channel indicating that it does not use the connection to the executor anymore.
case exitInfo = <-exit:
log.Info("Execution returned")
log.WithContext(wp.ctx).Info("Execution returned")
wp.Input.Stop()
wp.Output.SendExitInfo(&exitInfo)
}
@ -80,27 +81,30 @@ func (r *RunnerController) connectToRunner(writer http.ResponseWriter, request *
executionID := request.URL.Query().Get(ExecutionIDKey)
if !targetRunner.ExecutionExists(executionID) {
writeClientError(writer, ErrUnknownExecutionID, http.StatusNotFound)
writeClientError(writer, ErrUnknownExecutionID, http.StatusNotFound, request.Context())
return
}
connection, err := upgradeConnection(writer, request)
if err != nil {
writeInternalServerError(writer, err, dto.ErrorUnknown)
writeInternalServerError(writer, err, dto.ErrorUnknown, request.Context())
return
}
// ToDo: Why can we not inherit from request.Context() here?
proxyCtx, cancelProxy := context.WithCancel(context.Background())
proxyCtx = sentry.SetHubOnContext(proxyCtx, sentry.GetHubFromContext(request.Context()))
defer cancelProxy()
proxy := newWebSocketProxy(connection, proxyCtx)
log.WithField("runnerId", targetRunner.ID()).
log.WithContext(proxyCtx).WithField("runnerId", targetRunner.ID()).
WithField("executionID", logging.RemoveNewlineSymbol(executionID)).
Info("Running execution")
logging.StartSpan("api.runner.connect", "Execute Interactively", request.Context(), func(ctx context.Context) {
exit, cancel, err := targetRunner.ExecuteInteractively(executionID,
proxy.Input, proxy.Output.StdOut(), proxy.Output.StdErr(), ctx)
if err != nil {
log.WithError(err).Warn("Cannot execute request.")
log.WithContext(ctx).WithError(err).Warn("Cannot execute request.")
return // The proxy is stopped by the deferred cancel.
}

View File

@ -80,7 +80,7 @@ func (cr *codeOceanToRawReader) readInputLoop(ctx context.Context) {
case <-readMessage:
}
if inputContainsError(messageType, err) {
if inputContainsError(messageType, err, loopContext) {
return
}
if handleInput(reader, cr.buffer, loopContext) {
@ -93,11 +93,11 @@ func (cr *codeOceanToRawReader) readInputLoop(ctx context.Context) {
func handleInput(reader io.Reader, buffer chan byte, ctx context.Context) (done bool) {
message, err := io.ReadAll(reader)
if err != nil {
log.WithError(err).Warn("error while reading WebSocket message")
log.WithContext(ctx).WithError(err).Warn("error while reading WebSocket message")
return true
}
log.WithField("message", string(message)).Trace("Received message from client")
log.WithContext(ctx).WithField("message", string(message)).Trace("Received message from client")
for _, character := range message {
select {
case <-ctx.Done():
@ -108,17 +108,17 @@ func handleInput(reader io.Reader, buffer chan byte, ctx context.Context) (done
return false
}
func inputContainsError(messageType int, err error) (done bool) {
func inputContainsError(messageType int, err error, ctx context.Context) (done bool) {
if err != nil && websocket.IsCloseError(err, websocket.CloseNormalClosure) {
log.Debug("ReadInputLoop: The client closed the connection!")
log.WithContext(ctx).Debug("ReadInputLoop: The client closed the connection!")
// The close handler will do something soon.
return true
} else if err != nil {
log.WithError(err).Warn("Error reading client message")
log.WithContext(ctx).WithError(err).Warn("Error reading client message")
return true
}
if messageType != websocket.TextMessage {
log.WithField("messageType", messageType).Warn("Received message of wrong type")
log.WithContext(ctx).WithField("messageType", messageType).Warn("Received message of wrong type")
return true
}
return false