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

@@ -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"
       }
     },
     {

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
 }
 

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

pkg/jmap/error.go

@@ -41,6 +41,7 @@ const (
 	JmapErrorInvalidObjectState
 	JmapErrorPatchObjectSerialization
 	JmapErrorInvalidProperties
+	JmapErrorRequestTracing
 )
 
 var (

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 {

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"),

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 {

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",

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"`
 }

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")
 			}

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 {

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}