From 17d4dd3a5b05b8f8b737490fd1d9862769b0d2a4 Mon Sep 17 00:00:00 2001 From: Pascal Bleser Date: Thu, 2 Jul 2026 17:08:56 +0200 Subject: [PATCH] groupware: add better HTTP logging * introduce configuration settings for TLS insecurity, tracing requests and responses * use more secure implementation when replacing JMAP placeholders in URL templates, path escaping them to avoid injection * add more efficient tracing of HTTP requests and responses between the Groupware backend and the JMAP server, with the possibility of specifying a maximum body size to trace, to avoid blowing up the logs * use more efficient string building for HTTP Authorization headers * change internal API to use streams (io.Reader) instead of reading JSON responses fully into memory before parsing them --- .vscode/launch.json | 13 +- pkg/jmap/api.go | 2 +- pkg/jmap/api_blob.go | 18 +- pkg/jmap/error.go | 1 + pkg/jmap/export_integration_test.go | 2 +- pkg/jmap/http.go | 335 ++++++++++++------ pkg/jmap/tools.go | 12 +- .../pkg/config/defaults/defaultconfig.go | 9 +- services/groupware/pkg/config/http.go | 19 +- services/groupware/pkg/groupware/api_blob.go | 4 +- services/groupware/pkg/groupware/framework.go | 7 +- services/groupware/pkg/groupware/session.go | 13 +- 12 files changed, 291 insertions(+), 144 deletions(-) diff --git a/.vscode/launch.json b/.vscode/launch.json index 84e6a4e454..30bba8a584 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -138,12 +138,17 @@ "OC_SERVICE_ACCOUNT_SECRET": "service-account-secret", "OC_ADD_RUN_SERVICES": "auth-api,groupware", + "GROUPWARE_LOG_LEVEL": "trace", - + "GROUPWARE_HTTP_TRACE_REQUESTS": "true", + "GROUPWARE_HTTP_TRACE_MAX_REQUEST_BODY_SIZE": "8192", + "GROUPWARE_HTTP_TRACE_RESPONSES": "true", + "GROUPWARE_HTTP_TRACE_MAX_RESPONSE_BODY_SIZE": "8192", "GROUPWARE_JMAP_MASTER_USERNAME": "admin@example.org", "GROUPWARE_JMAP_MASTER_PASSWORD": "admin", - "GROUPWARE_SEND_DURATIONS_RESPONSE": "true", + "GROUPWARE_ALLOW_INSECURE_TLS": "true", + "GROUPWARE_ENABLE_MOCK_DATA": "true", "AUTHAPI_HTTP_ADDR": "0.0.0.0:10000", "AUTHAPI_AUTH_REQUIRE_SHARED_SECRET": "true", @@ -151,9 +156,7 @@ "WEB_ASSET_CORE_PATH": "${workspaceFolder}/../web/dist", "WEB_UI_CONFIG_FILE": "${workspaceFolder}/../web/dev/docker/opencloud.web.config.json", - "FRONTEND_GROUPWARE_ENABLED": "true", - - "GROUPWARE_ENABLE_MOCK_DATA": "true" + "FRONTEND_GROUPWARE_ENABLED": "true" } }, { diff --git a/pkg/jmap/api.go b/pkg/jmap/api.go index 3c9bc20dbf..b5910057e4 100644 --- a/pkg/jmap/api.go +++ b/pkg/jmap/api.go @@ -26,7 +26,7 @@ func (c Context) WithContext(newContext context.Context) Context { } type ApiClient interface { - Command(request Request, ctx Context) ([]byte, Language, Error) + Command(request Request, ctx Context) (io.ReadCloser, Language, Error) io.Closer } diff --git a/pkg/jmap/api_blob.go b/pkg/jmap/api_blob.go index 87be34a1ae..8d31d1e405 100644 --- a/pkg/jmap/api_blob.go +++ b/pkg/jmap/api_blob.go @@ -3,6 +3,7 @@ package jmap import ( "encoding/base64" "io" + "net/url" "strings" "github.com/opencloud-eu/opencloud/pkg/log" @@ -44,20 +45,21 @@ type UploadedBlobWithHash struct { func (j *Client) UploadBlobStream(accountId AccountId, contentType string, body io.Reader, ctx Context) (UploadedBlob, Language, error) { logger := log.From(ctx.Logger.With().Str(logEndpoint, ctx.Session.UploadEndpoint)) ctx = ctx.WithLogger(logger) - // TODO(pbleser-oc) use a library for proper URL template parsing - uploadUrl := strings.ReplaceAll(ctx.Session.UploadUrlTemplate, "{accountId}", string(accountId)) + uploadUrl := strings.NewReplacer( + "{accountId}", url.PathEscape(string(accountId)), + ).Replace(ctx.Session.UploadUrlTemplate) return j.blob.UploadBinary(uploadUrl, ctx.Session.UploadEndpoint, contentType, body, ctx) } func (j *Client) DownloadBlobStream(accountId AccountId, blobId string, name string, typ string, ctx Context) (*BlobDownload, Language, error) { //NOSONAR logger := log.From(ctx.Logger.With().Str(logEndpoint, ctx.Session.DownloadEndpoint)) ctx = ctx.WithLogger(logger) - // TODO(pbleser-oc) use a library for proper URL template parsing - downloadUrl := ctx.Session.DownloadUrlTemplate - downloadUrl = strings.ReplaceAll(downloadUrl, "{accountId}", string(accountId)) - downloadUrl = strings.ReplaceAll(downloadUrl, "{blobId}", blobId) - downloadUrl = strings.ReplaceAll(downloadUrl, "{name}", name) - downloadUrl = strings.ReplaceAll(downloadUrl, "{type}", typ) + downloadUrl := strings.NewReplacer( + "{accountId}", url.PathEscape(string(accountId)), + "{blobId}", url.PathEscape(blobId), + "{name}", url.PathEscape(name), + "{type}", url.PathEscape(typ), + ).Replace(ctx.Session.DownloadUrlTemplate) logger = log.From(logger.With().Str(logDownloadUrl, downloadUrl).Str(logBlobId, blobId)) return j.blob.DownloadBinary(downloadUrl, ctx.Session.DownloadEndpoint, ctx) } diff --git a/pkg/jmap/error.go b/pkg/jmap/error.go index d632b7bbfd..1274256249 100644 --- a/pkg/jmap/error.go +++ b/pkg/jmap/error.go @@ -41,6 +41,7 @@ const ( JmapErrorInvalidObjectState JmapErrorPatchObjectSerialization JmapErrorInvalidProperties + JmapErrorRequestTracing ) var ( diff --git a/pkg/jmap/export_integration_test.go b/pkg/jmap/export_integration_test.go index 6abc5018d6..83bed572b4 100644 --- a/pkg/jmap/export_integration_test.go +++ b/pkg/jmap/export_integration_test.go @@ -660,7 +660,7 @@ func createJmapClient(container *testcontainers.DockerContainer, ctx context.Con eventListener := nullHttpJmapApiClientEventListener{} - api := NewHttpJmapClient(&jh, auth, eventListener) + api := NewHttpJmapClient(&jh, auth, eventListener, true, 8192, true, 8192) wscf, err := NewHttpWsClientFactory(wsd, auth, logger, eventListener) if err != nil { diff --git a/pkg/jmap/http.go b/pkg/jmap/http.go index 9edc9227a8..aeecfd2d28 100644 --- a/pkg/jmap/http.go +++ b/pkg/jmap/http.go @@ -14,6 +14,8 @@ import ( "net/url" "slices" "strconv" + "strings" + "time" "github.com/gorilla/websocket" "github.com/opencloud-eu/opencloud/pkg/log" @@ -23,10 +25,14 @@ import ( // Implementation of ApiClient, SessionClient and BlobClient that uses // HTTP to perform JMAP operations. type HttpJmapClient struct { - client *http.Client - userAgent string - authenticator HttpJmapClientAuthenticator - listener HttpJmapApiClientEventListener + client *http.Client + userAgent string + authenticator HttpJmapClientAuthenticator + listener HttpJmapApiClientEventListener + traceRequests bool + traceMaxRequestBodySize int64 + traceResponses bool + traceMaxResponseBodySize int64 } var ( @@ -37,6 +43,8 @@ var ( const ( logEndpoint = "endpoint" + logUri = "uri" + logMethod = "method" logHttpStatus = "status" logHttpStatusCode = "status-code" logHttpUrl = "url" @@ -47,6 +55,8 @@ const ( logTypeRequest = "request" logTypeResponse = "response" logTypePush = "push" + logDuration = "duration" + logBodyTruncated = "truncated" ) // Record JMAP HTTP execution events that may occur, e.g. using metrics. @@ -103,21 +113,30 @@ func NewMasterAuthHttpJmapClientAuthenticator(masterUser string, masterPassword var _ HttpJmapClientAuthenticator = &MasterAuthHttpJmapClientAuthenticator{} -func (h *MasterAuthHttpJmapClientAuthenticator) Authenticate(ctx context.Context, username string, _ *log.Logger, req *http.Request) Error { - u := username +func (h *MasterAuthHttpJmapClientAuthenticator) auth(username string, headers http.Header) { + // not nice to read, but heavily optimized to prevent needless memory allocations, since + // this hot path will be used all the time + var sb strings.Builder + sb.WriteString("Basic ") + enc := base64.NewEncoder(base64.StdEncoding, &sb) + enc.Write([]byte(username)) if username != h.masterUser { - u = username + "%" + h.masterUser + enc.Write([]byte("%")) + enc.Write([]byte(h.masterUser)) } - req.SetBasicAuth(u, h.masterPassword) + enc.Write([]byte(":")) + enc.Write([]byte(h.masterPassword)) + enc.Close() + headers.Set("Authorization", sb.String()) +} + +func (h *MasterAuthHttpJmapClientAuthenticator) Authenticate(_ context.Context, username string, _ *log.Logger, req *http.Request) Error { + h.auth(username, req.Header) return nil } -func (h *MasterAuthHttpJmapClientAuthenticator) AuthenticateWS(ctx context.Context, username string, _ *log.Logger, headers http.Header) Error { - u := username - if username != h.masterUser { - u = username + "%" + h.masterUser - } - headers.Add("Authorization", "Basic "+base64.StdEncoding.EncodeToString([]byte(u+":"+h.masterPassword))) +func (h *MasterAuthHttpJmapClientAuthenticator) AuthenticateWS(_ context.Context, username string, _ *log.Logger, headers http.Header) Error { + h.auth(username, headers) return nil } @@ -126,12 +145,19 @@ func NullHttpJmapApiClientEventListener() HttpJmapApiClientEventListener { return nullHttpJmapApiClientEventListener{} } -func NewHttpJmapClient(client *http.Client, authenticator HttpJmapClientAuthenticator, listener HttpJmapApiClientEventListener) *HttpJmapClient { +func NewHttpJmapClient(client *http.Client, authenticator HttpJmapClientAuthenticator, listener HttpJmapApiClientEventListener, + traceRequests bool, traceMaxRequestBodySize int64, + traceResponses bool, traceMaxResponseBodySize int64, +) *HttpJmapClient { return &HttpJmapClient{ - client: client, - authenticator: authenticator, - userAgent: "OpenCloud/" + version.GetString(), - listener: listener, + client: client, + authenticator: authenticator, + userAgent: "OpenCloud/" + version.GetString(), + listener: listener, + traceRequests: traceRequests, + traceMaxRequestBodySize: traceMaxRequestBodySize, + traceResponses: traceResponses, + traceMaxResponseBodySize: traceMaxResponseBodySize, } } @@ -159,6 +185,102 @@ var ( errNilBaseUrl = errors.New("sessionUrl is nil") ) +func (h *HttpJmapClient) beforeRequest(_ context.Context, logger *log.Logger, _ string, endpoint string, req *http.Request) Error { + l := logger.Trace() + if h.traceRequests && l.Enabled() { + var logBuilder bytes.Buffer + for key, values := range req.Header { + if key == "Authorization" { + continue + } + for _, value := range values { + fmt.Fprintf(&logBuilder, "%s: %s\n", key, value) + } + } + if h.traceMaxRequestBodySize >= 0 && req.Body != nil && req.Body != http.NoBody { + peekBuffer := new(bytes.Buffer) + limitedReader := io.LimitReader(req.Body, h.traceMaxRequestBodySize) + tee := io.TeeReader(limitedReader, peekBuffer) + if _, err := io.Copy(io.Discard, tee); err != nil { + return jmapError(fmt.Errorf("failed to peek at the request body for tracing: %v", err), JmapErrorRequestTracing) + } else { + logBuilder.Write(peekBuffer.Bytes()) + if int64(peekBuffer.Len()) >= h.traceMaxRequestBodySize { + l = l.Bool(logBodyTruncated, true) + } + fullBodyReader := io.MultiReader(peekBuffer, req.Body) + req.Body = io.NopCloser(fullBodyReader) + } + } + l.Str(logMethod, req.Method).Str(logUri, req.URL.String()). + Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeRequest). + Msg(logBuilder.String()) + } + return nil +} + +type httpResponseReadCloser struct { + io.Reader + body io.ReadCloser +} + +func (c httpResponseReadCloser) Close() error { + if c.body != nil { + return c.body.Close() + } + return nil +} + +func (h *HttpJmapClient) response(_ context.Context, logger *log.Logger, _ string, endpoint string, duration time.Duration, req *http.Request, resp *http.Response) (io.ReadCloser, error) { + l := logger.Trace() + if h.traceResponses && l.Enabled() { + var logBuilder bytes.Buffer + for key, values := range resp.Header { + for _, value := range values { + fmt.Fprintf(&logBuilder, "%s: %s\n", key, value) + } + } + + var peekBuffer *bytes.Buffer = nil + if h.traceMaxResponseBodySize > 0 { + peekBuffer = new(bytes.Buffer) + limitedReader := io.LimitReader(resp.Body, h.traceMaxResponseBodySize) + tee := io.TeeReader(limitedReader, peekBuffer) + if _, err := io.Copy(io.Discard, tee); err != nil { + if resp.Body != nil { + if err := resp.Body.Close(); err != nil { + logger.Error().Err(err).Msg("failed to close response body") //NOSONAR + } + } + return nil, err + } + + if int64(peekBuffer.Len()) >= h.traceMaxResponseBodySize { + l = l.Bool(logBodyTruncated, true) + } + + logBuilder.Write(peekBuffer.Bytes()) + } + + l.Str(logProto, logProtoJmap).Str(logType, logTypeResponse).Str(logEndpoint, endpoint). + Str(logMethod, req.Method).Str(logUri, req.URL.String()). + Str(logHttpStatus, log.SafeString(resp.Status)).Int(logHttpStatusCode, resp.StatusCode). + Dur(logDuration, duration). + Msg(logBuilder.String()) + + if peekBuffer != nil { + return httpResponseReadCloser{ + body: resp.Body, + Reader: io.MultiReader(peekBuffer, resp.Body), + }, nil + } else { + return resp.Body, nil + } + } else { + return resp.Body, nil + } +} + func (h *HttpJmapClient) GetSession(ctx context.Context, sessionUrl *url.URL, username string, logger *log.Logger) (SessionResponse, Error) { if sessionUrl == nil { logger.Error().Msg("sessionUrl is nil") @@ -179,17 +301,38 @@ func (h *HttpJmapClient) GetSession(ctx context.Context, sessionUrl *url.URL, us logger.Error().Err(err).Msgf("failed to create GET request for %v", sessionUrl) return SessionResponse{}, jmapError(err, JmapErrorInvalidHttpRequest) } + req.Header.Add("Cache-Control", "no-cache, no-store, must-revalidate") // spec recommendation + req.Header.Add("Content-Type", "application/json") //NOSONAR + req.Header.Add("User-Agent", h.userAgent) //NOSONAR + + if err := h.beforeRequest(ctx, logger, username, endpoint, req); err != nil { + return SessionResponse{}, err + } + if err := h.auth(ctx, username, logger, req); err != nil { return SessionResponse{}, err } - req.Header.Add("Cache-Control", "no-cache, no-store, must-revalidate") // spec recommendation + before := time.Now() res, err := h.client.Do(req) + duration := time.Since(before) if err != nil { h.listener.OnFailedRequest(endpoint, err) logger.Error().Err(err).Msgf("failed to perform GET %v", sessionUrl) return SessionResponse{}, jmapError(err, JmapErrorInvalidHttpRequest) } + + // dump the response regardless of the status code + body, err := h.response(ctx, logger, username, endpoint, duration, req, res) + + // since we are not returning a stream from this function, we have to close the response body + // before leaving the scope of the function + defer func() { + if err := body.Close(); err != nil { + logger.Error().Err(err).Msg("failed to close response body") //NOSONAR + } + }() + if res.StatusCode < 200 || res.StatusCode > 299 { h.listener.OnFailedRequestWithStatus(endpoint, res.StatusCode) logger.Error().Str(logHttpStatus, log.SafeString(res.Status)).Int(logHttpStatusCode, res.StatusCode).Msg("HTTP response status code is not 200") @@ -197,16 +340,6 @@ func (h *HttpJmapClient) GetSession(ctx context.Context, sessionUrl *url.URL, us } h.listener.OnSuccessfulRequest(endpoint, res.StatusCode) - if res.Body != nil { - defer func(Body io.ReadCloser) { - err := Body.Close() - if err != nil { - logger.Error().Err(err).Msg("failed to close response body") //NOSONAR - } - }(res.Body) - } - - body, err := io.ReadAll(res.Body) if err != nil { logger.Error().Err(err).Msg("failed to read response body") //NOSONAR h.listener.OnResponseBodyReadingError(endpoint, err) @@ -214,8 +347,7 @@ func (h *HttpJmapClient) GetSession(ctx context.Context, sessionUrl *url.URL, us } var data SessionResponse - err = json.Unmarshal(body, &data) - if err != nil { + if err := json.NewDecoder(body).Decode(&data); err != nil { logger.Error().Str(logHttpUrl, log.SafeString(sessionUrlStr)).Err(err).Msg("failed to decode JSON payload from .well-known/jmap response") h.listener.OnResponseBodyUnmarshallingError(endpoint, err) return SessionResponse{}, jmapError(err, JmapErrorDecodingResponseBody) @@ -224,7 +356,7 @@ func (h *HttpJmapClient) GetSession(ctx context.Context, sessionUrl *url.URL, us return data, nil } -func (h *HttpJmapClient) Command(request Request, ctx Context) ([]byte, Language, Error) { //NOSONAR +func (h *HttpJmapClient) Command(request Request, ctx Context) (io.ReadCloser, Language, Error) { //NOSONAR session := ctx.Session logger := ctx.Logger acceptLanguage := ctx.AcceptLanguage @@ -255,55 +387,42 @@ func (h *HttpJmapClient) Command(request Request, ctx Context) ([]byte, Language req.Header.Add("Content-Type", "application/json") //NOSONAR req.Header.Add("User-Agent", h.userAgent) //NOSONAR - if logger.Trace().Enabled() { - requestBytes, err := httputil.DumpRequestOut(req, true) - if err == nil { - logger.Trace().Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeRequest).Msg(string(requestBytes)) - } - } + h.beforeRequest(cotx, logger, session.Username, endpoint, req) + if err := h.auth(cotx, session.Username, logger, req); err != nil { return nil, "", err } + before := time.Now() res, err := h.client.Do(req) + duration := time.Since(before) if err != nil { h.listener.OnFailedRequest(endpoint, err) logger.Error().Err(err).Msgf("failed to perform POST %v", jmapUrl) return nil, "", jmapError(err, JmapErrorSendingRequest) } - if logger.Trace().Enabled() { - responseBytes, err := httputil.DumpResponse(res, true) - if err == nil { - logger.Trace().Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeResponse). - Str(logHttpStatus, log.SafeString(res.Status)).Int(logHttpStatusCode, res.StatusCode). - Msg(string(responseBytes)) - } - } + // note that we are omitting the usual deferred response body closer here since we are returning + // an io.ReadCloser to the body and if we close it when leaving the scope of this function, the + // caller won't be able to read the response; instead, it is up to the caller to close the + // ReadCloser we are returning from here + body, err := h.response(cotx, logger, session.Username, endpoint, duration, req, res) language := Language(res.Header.Get("Content-Language")) //NOSONAR - if res.StatusCode < 200 || res.StatusCode > 299 { - h.listener.OnFailedRequestWithStatus(endpoint, res.StatusCode) - logger.Error().Str(logEndpoint, endpoint).Str(logHttpStatus, log.SafeString(res.Status)).Msg("HTTP response status code is not 2xx") //NOSONAR - return nil, language, jmapError(err, JmapErrorServerResponse) - } - if res.Body != nil { - defer func(Body io.ReadCloser) { - err := Body.Close() - if err != nil { - logger.Error().Err(err).Msg("failed to close response body") - } - }(res.Body) - } - h.listener.OnSuccessfulRequest(endpoint, res.StatusCode) - - body, err := io.ReadAll(res.Body) if err != nil { logger.Error().Err(err).Msg("failed to read response body") h.listener.OnResponseBodyReadingError(endpoint, err) return nil, language, jmapError(err, JmapErrorServerResponse) } + if res.StatusCode < 200 || res.StatusCode > 299 { + h.listener.OnFailedRequestWithStatus(endpoint, res.StatusCode) + logger.Error().Str(logEndpoint, endpoint).Str(logHttpStatus, log.SafeString(res.Status)).Msg("HTTP response status code is not 2xx") //NOSONAR + return nil, language, jmapError(err, JmapErrorServerResponse) + } + + h.listener.OnSuccessfulRequest(endpoint, res.StatusCode) + return body, language, nil } @@ -325,58 +444,51 @@ func (h *HttpJmapClient) UploadBinary(uploadUrl string, endpoint string, content if acceptLanguage != "" { req.Header.Add("Accept-Language", acceptLanguage) } - if logger.Trace().Enabled() { - requestBytes, err := httputil.DumpRequestOut(req, false) - if err == nil { - logger.Trace().Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeRequest).Msg(string(requestBytes)) - } - } + h.beforeRequest(cotx, logger, session.Username, endpoint, req) if err := h.auth(cotx, session.Username, logger, req); err != nil { return UploadedBlob{}, "", err } + before := time.Now() res, err := h.client.Do(req) + duration := time.Since(before) if err != nil { h.listener.OnFailedRequest(endpoint, err) logger.Error().Err(err).Msgf("failed to perform POST %v", uploadUrl) return UploadedBlob{}, "", jmapError(err, JmapErrorSendingRequest) } - if logger.Trace().Enabled() { - responseBytes, err := httputil.DumpResponse(res, true) - if err == nil { - logger.Trace().Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeResponse). - Str(logHttpStatus, log.SafeString(res.Status)).Int(logHttpStatusCode, res.StatusCode). - Msg(string(responseBytes)) + + // note that we are omitting the usual deferred response body closer here since we are returning + // an io.ReadCloser to the body and if we close it when leaving the scope of this function, the + // caller won't be able to read the response; instead, it is up to the caller to close the + // ReadCloser we are returning from here + + responseBody, err := h.response(cotx, logger, session.Username, endpoint, duration, req, res) + + // since we are not returning a stream from this function, we have to close the response body + // before leaving the scope of the function + defer func() { + if err := responseBody.Close(); err != nil { + logger.Error().Err(err).Msg("failed to close response body") //NOSONAR } - } - + }() language := Language(res.Header.Get("Content-Language")) - if res.StatusCode < 200 || res.StatusCode > 299 { - h.listener.OnFailedRequestWithStatus(endpoint, res.StatusCode) - logger.Error().Str(logHttpStatus, log.SafeString(res.Status)).Int(logHttpStatusCode, res.StatusCode).Msg("HTTP response status code is not 2xx") - return UploadedBlob{}, language, jmapError(err, JmapErrorServerResponse) - } - if res.Body != nil { - defer func(Body io.ReadCloser) { - err := Body.Close() - if err != nil { - logger.Error().Err(err).Msg("failed to close response body") - } - }(res.Body) - } - h.listener.OnSuccessfulRequest(endpoint, res.StatusCode) - - responseBody, err := io.ReadAll(res.Body) if err != nil { logger.Error().Err(err).Msg("failed to read response body") h.listener.OnResponseBodyReadingError(endpoint, err) return UploadedBlob{}, language, jmapError(err, JmapErrorServerResponse) } + if res.StatusCode < 200 || res.StatusCode > 299 { + h.listener.OnFailedRequestWithStatus(endpoint, res.StatusCode) + logger.Error().Str(logHttpStatus, log.SafeString(res.Status)).Int(logHttpStatusCode, res.StatusCode).Msg("HTTP response status code is not 2xx") + return UploadedBlob{}, language, jmapError(err, JmapErrorServerResponse) + } + h.listener.OnSuccessfulRequest(endpoint, res.StatusCode) + var result UploadedBlob - err = json.Unmarshal(responseBody, &result) - if err != nil { + if err := json.NewDecoder(responseBody).Decode(&result); err != nil { logger.Error().Str(logHttpUrl, log.SafeString(uploadUrl)).Err(err).Msg("failed to decode JSON payload from the upload response") h.listener.OnResponseBodyUnmarshallingError(endpoint, err) return UploadedBlob{}, language, jmapError(err, JmapErrorDecodingResponseBody) @@ -402,32 +514,35 @@ func (h *HttpJmapClient) DownloadBinary(downloadUrl string, endpoint string, ctx if acceptLanguage != "" { req.Header.Add("Accept-Language", acceptLanguage) } - if logger.Trace().Enabled() { - requestBytes, err := httputil.DumpRequestOut(req, true) - if err == nil { - logger.Trace().Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeRequest).Msg(string(requestBytes)) - } - } + h.beforeRequest(cotx, logger, session.Username, endpoint, req) if err := h.auth(cotx, session.Username, logger, req); err != nil { return nil, "", err } + before := time.Now() res, err := h.client.Do(req) + duration := time.Since(before) if err != nil { h.listener.OnFailedRequest(endpoint, err) logger.Error().Err(err).Msgf("failed to perform GET %v", downloadUrl) return nil, "", jmapError(err, JmapErrorSendingRequest) } - if logger.Trace().Enabled() { - responseBytes, err := httputil.DumpResponse(res, false) - if err == nil { - logger.Trace().Str(logEndpoint, endpoint).Str(logProto, logProtoJmap).Str(logType, logTypeResponse). - Str(logHttpStatus, log.SafeString(res.Status)).Int(logHttpStatusCode, res.StatusCode). - Msg(string(responseBytes)) - } - } + + // note that we are omitting the usual deferred response body closer here since we are returning + // an io.ReadCloser to the body and if we close it when leaving the scope of this function, the + // caller won't be able to read the response; instead, it is up to the caller to close the + // ReadCloser we are returning from here + + responseBody, err := h.response(cotx, logger, session.Username, endpoint, duration, req, res) + language := Language(res.Header.Get("Content-Language")) + if err != nil { + logger.Error().Err(err).Msg("failed to read response body") + h.listener.OnResponseBodyReadingError(endpoint, err) + return nil, language, jmapError(err, JmapErrorServerResponse) + } + if res.StatusCode == http.StatusNotFound { return nil, language, nil } @@ -449,7 +564,7 @@ func (h *HttpJmapClient) DownloadBinary(downloadUrl string, endpoint string, ctx } return &BlobDownload{ - Body: res.Body, + Body: responseBody, Size: size, Type: res.Header.Get("Content-Type"), ContentDisposition: res.Header.Get("Content-Disposition"), diff --git a/pkg/jmap/tools.go b/pkg/jmap/tools.go index 7bb7d8c8c1..ffa7ced3f8 100644 --- a/pkg/jmap/tools.go +++ b/pkg/jmap/tools.go @@ -77,12 +77,18 @@ func command[T any](client Cmdr, //NOSONAR } var response Response - err := json.Unmarshal(responseBody, &response) - if err != nil { + if err := json.NewDecoder(responseBody).Decode(&response); err != nil { logger.Error().Err(err).Msgf("failed to deserialize body JSON payload into a %T", response) + if err := responseBody.Close(); err != nil { + logger.Error().Err(err).Msg("failed to close response body") //NOSONAR + } return ZeroResult[T](single(duration)), jmapError(err, JmapErrorDecodingResponseBody) } + if err := responseBody.Close(); err != nil { + logger.Error().Err(err).Msg("failed to close response body") //NOSONAR + } + if response.SessionState != ctx.Session.State { client.OnSessionOutdated(ctx.Session, response.SessionState) } @@ -126,7 +132,7 @@ func command[T any](client Cmdr, //NOSONAR code = JmapErrorAccountReadOnly } msg := fmt.Sprintf("found method level error in response '%v', type: '%v', description: '%v'", mr.Tag, errorParameters.Type, errorParameters.Description) - err = errors.New(msg) + err := errors.New(msg) logger.Warn().Int("code", code).Str("type", errorParameters.Type).Msg(msg) return newPartialResult[T](response.SessionState, language, single(duration)), jmapResponseError(code, err, errorParameters.Type, errorParameters.Description) } else { diff --git a/services/groupware/pkg/config/defaults/defaultconfig.go b/services/groupware/pkg/config/defaults/defaultconfig.go index 7e2e502029..50bb9a159b 100644 --- a/services/groupware/pkg/config/defaults/defaultconfig.go +++ b/services/groupware/pkg/config/defaults/defaultconfig.go @@ -52,8 +52,13 @@ func DefaultConfig() *config.Config { AllowedHeaders: []string{"Authorization", "Origin", "Content-Type", "Accept", "X-Requested-With", "X-Request-Id", "Trace-Id", "Cache-Control"}, AllowCredentials: true, }, - OpenCloudPublicURL: "https://localhost:9200/", - SendDurationsResponse: false, + OpenCloudPublicURL: "https://localhost:9200/", + SendDurationsResponse: false, + Insecure: false, + TraceRequests: true, + TraceMaxRequestBodySize: 4 * 1024, + TraceResponses: true, + TraceMaxResponseBodySize: 4 * 1024, }, Service: config.Service{ Name: "groupware", diff --git a/services/groupware/pkg/config/http.go b/services/groupware/pkg/config/http.go index d939ed4036..4f4a507459 100644 --- a/services/groupware/pkg/config/http.go +++ b/services/groupware/pkg/config/http.go @@ -12,11 +12,16 @@ type CORS struct { // HTTP defines the available http configuration. type HTTP struct { - Addr string `yaml:"addr" env:"GROUPWARE_HTTP_ADDR" desc:"The bind address of the HTTP service." introductionVersion:"1.0.0"` - TLS shared.HTTPServiceTLS `yaml:"tls"` - Root string `yaml:"root" env:"GROUPWARE_HTTP_ROOT" desc:"Subdirectory that serves as the root for this HTTP service." introductionVersion:"1.0.0"` - Namespace string `yaml:"-"` - CORS CORS `yaml:"cors"` - OpenCloudPublicURL string `yaml:"opencloud_public_url" env:"OC_URL;OC_PUBLIC_URL;GROUPWARE_PUBLIC_URL"` - SendDurationsResponse bool `yaml:"send_durations_response" env:"GROUPWARE_SEND_DURATIONS_RESPONSE"` + Addr string `yaml:"addr" env:"GROUPWARE_HTTP_ADDR" desc:"The bind address of the HTTP service." introductionVersion:"1.0.0"` + TLS shared.HTTPServiceTLS `yaml:"tls"` + Root string `yaml:"root" env:"GROUPWARE_HTTP_ROOT" desc:"Subdirectory that serves as the root for this HTTP service." introductionVersion:"1.0.0"` + Namespace string `yaml:"-"` + CORS CORS `yaml:"cors"` + OpenCloudPublicURL string `yaml:"opencloud_public_url" env:"OC_URL;OC_PUBLIC_URL;GROUPWARE_PUBLIC_URL"` + SendDurationsResponse bool `yaml:"send_durations_response" env:"GROUPWARE_SEND_DURATIONS_RESPONSE"` + Insecure bool `yaml:"insecure" env:"GROUPWARE_ALLOW_INSECURE_TLS"` + TraceRequests bool `yaml:"trace_requests" env:"GROUPWARE_HTTP_TRACE_REQUESTS"` + TraceMaxRequestBodySize int64 `yaml:"trace_max_request_body_size" env:"GROUPWARE_HTTP_TRACE_MAX_REQUEST_BODY_SIZE"` + TraceResponses bool `yaml:"trace_responses" env:"GROUPWARE_HTTP_TRACE_RESPONSES"` + TraceMaxResponseBodySize int64 `yaml:"trace_max_response_body_size" env:"GROUPWARE_HTTP_TRACE_MAX_RESPONSE_BODY_SIZE"` } diff --git a/services/groupware/pkg/groupware/api_blob.go b/services/groupware/pkg/groupware/api_blob.go index 9290e34287..c46219ba38 100644 --- a/services/groupware/pkg/groupware/api_blob.go +++ b/services/groupware/pkg/groupware/api_blob.go @@ -84,8 +84,8 @@ func (r *Request) serveBlob(blobId string, name string, typ string, ctx jmap.Con } blob, lang, jerr := r.g.jmap.DownloadBlobStream(accountId, blobId, name, typ, ctx) if blob != nil && blob.Body != nil { - defer func(Body io.ReadCloser) { - err := Body.Close() + defer func(body io.ReadCloser) { + err := body.Close() if err != nil { ctx.Logger.Error().Err(err).Msg("failed to close response body") } diff --git a/services/groupware/pkg/groupware/framework.go b/services/groupware/pkg/groupware/framework.go index 9215fcd9d1..45c5e750aa 100644 --- a/services/groupware/pkg/groupware/framework.go +++ b/services/groupware/pkg/groupware/framework.go @@ -55,6 +55,7 @@ const ( logNewState = "new-state" logCacheEvictionReason = "reason" logCacheType = "type" + logDuration = "duration" ) // Minimalistic representation of a user, containing only the attributes that are @@ -205,7 +206,7 @@ func NewGroupware(config *config.Config, logger *log.Logger, mux *chi.Mux, prome useDnsForSessionResolution := false // TODO configuration setting, although still experimental, needs proper unit tests first - insecureTls := true // TODO make configurable + insecureTls := config.HTTP.Insecure sanitize := true // TODO make configurable @@ -247,6 +248,10 @@ func NewGroupware(config *config.Config, logger *log.Logger, mux *chi.Mux, prome &httpClient, auth, jmapMetricsAdapter, + config.HTTP.TraceRequests, + config.HTTP.TraceMaxRequestBodySize, + config.HTTP.TraceResponses, + config.HTTP.TraceMaxResponseBodySize, ) defer func() { if err := api.Close(); err != nil { diff --git a/services/groupware/pkg/groupware/session.go b/services/groupware/pkg/groupware/session.go index 3feac3a763..f29ed7b7f9 100644 --- a/services/groupware/pkg/groupware/session.go +++ b/services/groupware/pkg/groupware/session.go @@ -118,21 +118,26 @@ var _ jmap.SessionEventListener = &ttlcacheSessionCache{} func (c *ttlcacheSessionCache) load(key sessionCacheKey, ctx context.Context) cachedSession { username := key.username() + logger := log.From(c.logger.With().Str(logUsername, username)) sessionUrl, gwerr := c.sessionUrlProvider(ctx, username) if gwerr != nil { - c.logger.Warn().Str(logUsername, username).Str(logErrorCode, gwerr.Code).Msgf("failed to determine session URL for '%v'", key) + logger.Warn().Str(logErrorCode, gwerr.Code).Msgf("failed to determine session URL for '%v'", key) now := time.Now() until := now.Add(c.errorTtl) return failedSession{since: now, until: until, err: gwerr} } - session, jerr := c.sessionSupplier(ctx, sessionUrl, username, c.logger) + before := time.Now() + session, jerr := c.sessionSupplier(ctx, sessionUrl, username, logger) + duration := time.Since(before) if jerr != nil { - c.logger.Warn().Str(logUsername, username).Err(jerr).Msgf("failed to create session for '%v'", key) + logger.Warn().Err(jerr).Msgf("failed to create session for '%v'", key) now := time.Now() until := now.Add(c.errorTtl) return failedSession{since: now, until: until, err: groupwareErrorFromJmap(jerr)} } else { - c.logger.Debug().Str(logUsername, username).Msgf("successfully created session for '%v'", key) + if logger.Debug().Enabled() { + logger.Debug().Dur(logDuration, duration).Msgf("successfully created session for '%v' in %f.2ms", key, float64(duration.Microseconds())/float64(1000.0)) + } now := time.Now() until := now.Add(c.successTtl) return succeededSession{since: now, until: until, session: session}