gotenberg/pkg/modules/api/middlewares.go

package api

import (
	"bufio"
	"bytes"
	"context"
	"encoding/json"
	"errors"
	"fmt"
	"net/http"
	"os"
	"path/filepath"
	"regexp"
	"strconv"
	"strings"
	"time"

	"github.com/google/uuid"
	"github.com/hashicorp/go-retryablehttp"
	"github.com/labstack/echo/v4"
	"go.uber.org/zap"
)

// httpErrorHandler is the centralized HTTP error handler. It parses the error,
// returns either a response as "text/plain; charset=UTF-8" or, if a webhook
// client exists in the echo.Context, sends a request to the webhook error URL
// with a JSON body containing the trace, the status and the error message.
func httpErrorHandler(traceHeader string) echo.HTTPErrorHandler {
	return func(err error, c echo.Context) {
		parseError := func(err error) (int, string) {
			echoErr, ok := err.(*echo.HTTPError)
			if ok {
				return echoErr.Code, http.StatusText(echoErr.Code)
			}

			if errors.Is(err, context.DeadlineExceeded) {
				return http.StatusServiceUnavailable, http.StatusText(http.StatusServiceUnavailable)
			}

			var httpErr HTTPError
			if errors.As(err, &httpErr) {
				return httpErr.HTTPError()
			}

			// Default 500 status code.
			return http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError)
		}

		status, message := parseError(err)

		logger := c.Get("logger").(*zap.Logger)
		clientOrNil := c.Get("webhookClient")

		// No webhook client, meaning we can send the error as a response.
		if clientOrNil == nil {
			c.Response().Header().Add(echo.HeaderContentType, echo.MIMETextPlainCharsetUTF8)

			err = c.String(status, message)

			if err != nil {
				logger.Error(fmt.Sprintf("send error response: %s", err.Error()))
			}

			return
		}

		// We have to send the error to the webhook.
		client := clientOrNil.(*webhookClient)

		body := struct {
			Status  int    `json:"status"`
			Message string `json:"message"`
		}{
			Status:  status,
			Message: message,
		}

		b, err := json.Marshal(body)
		if err != nil {
			logger.Error(fmt.Sprintf("marshal JSON: %s", err.Error()))

			return
		}

		headers := map[string]string{
			echo.HeaderContentType: echo.MIMEApplicationJSONCharsetUTF8,
			traceHeader:            c.Get("trace").(string),
		}

		err = client.send(bytes.NewReader(b), headers, true)
		if err != nil {
			logger.Error(fmt.Sprintf("send error response to webhook: %s", err.Error()))
		}
	}
}

// latencyMiddleware sets the start time in the echo.Context under "startTime".
// Its value will be used later to calculate a request latency.
//
//  startTime := c.Get("startTime").(time.Time)
func latencyMiddleware() echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			// First piece for calculating the latency.
			startTime := time.Now()
			c.Set("startTime", startTime)

			// Call the next middleware in the chain.
			return next(c)
		}
	}
}

// rootPathMiddleware sets the root path in the echo.Context under "rootPath".
// Its value may be used to skip a middleware execution based on a request
// URI.
//
//  rootPath := c.Get("rootPath").(string)
//  healthURI := fmt.Sprintf("%shealth", rootPath)
//
//  // Skip the middleware if health check URI.
//  if c.Request().RequestURI == healthURI {
//    // Call the next middleware in the chain.
//    return next(c)
//  }
func rootPathMiddleware(rootPath string) echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			c.Set("rootPath", rootPath)

			// Call the next middleware in the chain.
			return next(c)
		}
	}
}

// traceMiddleware sets the request identifier in the echo.Context under
// "trace". Its value is either retrieved from the trace header or generated if
// the header is not present / its value is empty.
//
//  trace := c.Get("trace").(string)
func traceMiddleware(header string) echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			// Get or create the request identifier.
			trace := c.Request().Header.Get(header)

			if trace == "" {
				trace = uuid.New().String()
			}

			c.Set("trace", trace)
			c.Response().Header().Add(header, trace)

			// Call the next middleware in the chain.
			return next(c)
		}
	}
}

// loggerMiddleware sets the logger in the echo.Context under "logger" and logs
// a request result (but does not log a webhook call result, which is the job
// of the webhookClient).
//
//  logger := c.Get("logger").(*zap.Logger)
func loggerMiddleware(logger *zap.Logger, skipHealthRouteLogging bool) echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			startTime := c.Get("startTime").(time.Time)
			trace := c.Get("trace").(string)

			// Create the request logger and add it to our locals.
			reqLogger := logger.With(zap.String("trace", trace))
			c.Set("logger", reqLogger)

			// Call the next middleware in the chain.
			err := next(c)
			if err != nil {
				c.Error(err)
			}

			if skipHealthRouteLogging {
				rootPath := c.Get("rootPath").(string)
				healthURI := fmt.Sprintf("%shealth", rootPath)

				if c.Request().RequestURI == healthURI {
					return nil
				}
			}

			// Last piece for calculating the latency.
			finishTime := time.Now()

			// Now, let's log!
			fields := make([]zap.Field, 12)
			fields[0] = zap.String("remote_ip", c.RealIP())
			fields[1] = zap.String("host", c.Request().Host)
			fields[2] = zap.String("uri", c.Request().RequestURI)
			fields[3] = zap.String("method", c.Request().Method)
			fields[4] = zap.String("path", func() string {
				path := c.Request().URL.Path

				if path == "" {
					path = "/"
				}

				return path
			}())
			fields[5] = zap.String("referer", c.Request().Referer())
			fields[6] = zap.String("user_agent", c.Request().UserAgent())
			fields[7] = zap.Int("status", c.Response().Status)
			fields[8] = zap.Int64("latency", int64(finishTime.Sub(startTime)))
			fields[9] = zap.String("latency_human", finishTime.Sub(startTime).String())
			fields[10] = zap.Int64("bytes_in", c.Request().ContentLength)
			fields[11] = zap.Int64("bytes_out", c.Response().Size)

			if err != nil {
				reqLogger.Error(err.Error(), fields...)
			} else {
				reqLogger.Info("request handled", fields...)
			}

			return nil
		}
	}
}

type contextMiddlewareConfig struct {
	traceHeader string
	timeout     struct {
		process time.Duration
		write   time.Duration
	}
	webhook struct {
		allowList      *regexp.Regexp
		denyList       *regexp.Regexp
		errorAllowList *regexp.Regexp
		errorDenyList  *regexp.Regexp
		maxRetry       int
		retryMinWait   time.Duration
		retryMaxWait   time.Duration
		disable        bool
	}
}

// contextMiddleware handles the result of a "multipart/form-data" request. If
// a webhook URL is present in the headers, exit early and process the result
// in a goroutine.
func contextMiddleware(cfg contextMiddlewareConfig) echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			webhookURL := c.Request().Header.Get("Gotenberg-Webhook-Url")
			logger := c.Get("logger").(*zap.Logger).With(zap.Bool("webhook", webhookURL != ""))

			// We create a context with a timeout so that underlying processes are
			// able to stop early and handle correctly a timeout scenario.
			ctx, cancel, err := newContext(c, logger, cfg.timeout.process)
			if err != nil {
				cancel()

				return fmt.Errorf("create request context: %w", err)
			}
			c.Set("context", ctx)

			// Helper function for retrieving/creating the output filename.
			outputFilename := func(outputPath string) string {
				filename := c.Request().Header.Get("Gotenberg-Output-Filename")

				if filename == "" {
					return filepath.Base(outputPath)
				}

				return fmt.Sprintf("%s%s", filename, filepath.Ext(outputPath))
			}

			if webhookURL == "" {
				defer cancel()

				// No webhook URL, call the next middleware in the chain.
				err := next(c)

				if err != nil {
					return err
				}

				// No error, let's build the output file.
				outputPath, err := ctx.buildOutputFile()
				if err != nil {
					return fmt.Errorf("build output file: %w", err)
				}

				// Send the output file.
				err = c.Attachment(outputPath, outputFilename(outputPath))
				if err != nil {
					return fmt.Errorf("send response: %w", err)
				}

				return nil
			}

			// Ok, we got a webhook URL.

			if cfg.webhook.disable {
				// The client requested the webhook feature, but it has been
				// disabled. Let's tell the client about that.
				cancel()

				return WrapError(
					errors.New("webhook feature requested but it is disabled"),
					NewSentinelHTTPError(http.StatusForbidden, "Invalid 'Gotenberg-Webhook-Url' header: feature is disabled"),
				)
			}

			// Do we have a webhook error URL in case of... error?
			webhookErrorURL := c.Request().Header.Get("Gotenberg-Webhook-Error-Url")

			if webhookErrorURL == "" {
				cancel()

				return WrapError(
					errors.New("empty webhook error URL"),
					NewSentinelHTTPError(http.StatusBadRequest, "Invalid 'Gotenberg-Webhook-Error-Url' header: empty value or header not provided"),
				)
			}

			// Let's check if the webhook URLs are acceptable according to our
			// allowed/denied lists.
			filter := func(URL, header string, allowList, denyList *regexp.Regexp) error {
				if !allowList.MatchString(URL) {
					return WrapError(
						fmt.Errorf("'%s' does not match the expression from the allowed list", URL),
						NewSentinelHTTPError(
							http.StatusForbidden,
							fmt.Sprintf("Invalid '%s' header value: '%s' does not match the authorized URLs", header, URL),
						),
					)
				}

				if denyList.String() != "" && denyList.MatchString(URL) {
					return WrapError(
						fmt.Errorf("'%s' matches the expression from the denied list", URL),
						NewSentinelHTTPError(
							http.StatusForbidden,
							fmt.Sprintf("Invalid '%s' header value: '%s' does not match the authorized URLs", header, URL),
						),
					)
				}

				return nil
			}

			err = filter(webhookURL, "Gotenberg-Webhook-Url", cfg.webhook.allowList, cfg.webhook.denyList)
			if err != nil {
				cancel()

				return fmt.Errorf("filter webhook URL: %w", err)
			}

			err = filter(webhookErrorURL, "Gotenberg-Webhook-Error-Url", cfg.webhook.errorAllowList, cfg.webhook.errorDenyList)
			if err != nil {
				cancel()

				return fmt.Errorf("filter webhook error URL: %w", err)
			}

			// Let's check the HTTP methods for calling the webhook URLs.
			methodFromHeader := func(header string) (string, error) {
				method := c.Request().Header.Get(header)

				if method == "" {
					return http.MethodPost, nil
				}

				method = strings.ToUpper(method)

				switch method {
				case http.MethodPost:
					return method, nil
				case http.MethodPatch:
					return method, nil
				case http.MethodPut:
					return method, nil
				}

				return "", WrapError(
					fmt.Errorf("webhook method '%s' is not '%s', '%s' or '%s'", method, http.MethodPost, http.MethodPatch, http.MethodPut),
					NewSentinelHTTPError(
						http.StatusBadRequest,
						fmt.Sprintf("Invalid '%s' header value: expected '%s', '%s' or '%s', but got '%s'", header, http.MethodPost, http.MethodPatch, http.MethodPut, method),
					),
				)
			}

			webhookMethod, err := methodFromHeader("Gotenberg-Webhook-Method")
			if err != nil {
				cancel()

				return fmt.Errorf("get method to use for webhook: %w", err)
			}

			webhookErrorMethod, err := methodFromHeader("Gotenberg-Webhook-Error-Method")
			if err != nil {
				cancel()

				return fmt.Errorf("get method to use for webhook error: %w", err)
			}

			// What about extra HTTP headers?
			var extraHTTPHeaders map[string]string

			extraHTTPHeadersJSON := c.Request().Header.Get("Gotenberg-Webhook-Extra-Http-Headers")
			if extraHTTPHeadersJSON != "" {
				err = json.Unmarshal([]byte(extraHTTPHeadersJSON), &extraHTTPHeaders)
				if err != nil {
					cancel()

					return WrapError(
						fmt.Errorf("unmarshal webhook extra HTTP headers: %w", err),
						NewSentinelHTTPError(http.StatusBadRequest, fmt.Sprintf("Invalid 'Gotenberg-Webhook-Extra-Http-Headers' header value: %s", err.Error())),
					)
				}
			}

			client := &webhookClient{
				url:              webhookURL,
				method:           webhookMethod,
				errorURL:         webhookErrorURL,
				errorMethod:      webhookErrorMethod,
				extraHTTPHeaders: extraHTTPHeaders,
				startTime:        c.Get("startTime").(time.Time),

				client: &retryablehttp.Client{
					HTTPClient: &http.Client{
						Timeout: cfg.timeout.write,
					},
					RetryMax:     cfg.webhook.maxRetry,
					RetryWaitMin: cfg.webhook.retryMinWait,
					RetryWaitMax: cfg.webhook.retryMaxWait,
					Logger: leveledLogger{
						logger: logger,
					},
					CheckRetry: retryablehttp.DefaultRetryPolicy,
					Backoff:    retryablehttp.DefaultBackoff,
				},
				logger: logger,
			}

			c.Set("webhookClient", client)

			// As a webhook URL has been given, we handle the request in a
			// goroutine and return immediately.
			go func() {
				defer cancel()

				// Call the next middleware in the chain.
				err := next(c)

				if err != nil {
					// The process failed for whatever reason. Let's send the
					// details to the webhook.
					ctx.Log().Error(err.Error())
					c.Error(err)

					return
				}

				// No error, let's get build the output file.
				outputPath, err := ctx.buildOutputFile()
				if err != nil {
					ctx.Log().Error(fmt.Sprintf("build output file: %s", err))
					c.Error(err)

					return
				}

				outputFile, err := os.Open(outputPath)
				if err != nil {
					ctx.Log().Error(fmt.Sprintf("open output file: %s", err))
					c.Error(err)

					return
				}

				defer func() {
					err := outputFile.Close()
					if err != nil {
						ctx.Log().Error(fmt.Sprintf("close output file: %s", err))
					}
				}()

				fileHeader := make([]byte, 512)
				_, err = outputFile.Read(fileHeader)
				if err != nil {
					ctx.Log().Error(fmt.Sprintf("read header of output file: %s", err))
					c.Error(err)

					return
				}

				fileStat, err := outputFile.Stat()
				if err != nil {
					ctx.Log().Error(fmt.Sprintf("get stat from output file: %s", err))
					c.Error(err)

					return
				}

				_, err = outputFile.Seek(0, 0)
				if err != nil {
					ctx.Log().Error(fmt.Sprintf("reset output file reader: %s", err))
					c.Error(err)

					return
				}

				headers := map[string]string{
					echo.HeaderContentDisposition: fmt.Sprintf("attachement; filename=%q", outputFilename(outputPath)),
					echo.HeaderContentType:        http.DetectContentType(fileHeader),
					echo.HeaderContentLength:      strconv.FormatInt(fileStat.Size(), 10),
					cfg.traceHeader:               c.Get("trace").(string),
				}

				// Send the output file to the webhook.
				err = client.send(bufio.NewReader(outputFile), headers, false)
				if err != nil {
					ctx.Log().Error(fmt.Sprintf("send output file to webhook: %s", err))
					c.Error(err)
				}
			}()

			return c.NoContent(http.StatusNoContent)
		}
	}
}

// timeoutMiddleware manages hard timeout scenarios, i.e., when a route handler
// fails to timeout as expected.
func timeoutMiddleware(hardTimeout time.Duration) echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			logger := c.Get("logger").(*zap.Logger)

			// Define a hard timeout if the route handler fails to timeout as
			// expected.
			hardTimeoutCtx, hardTimeoutCancel := context.WithTimeout(
				context.Background(),
				hardTimeout,
			)
			defer hardTimeoutCancel()

			errChan := make(chan error, 1)

			go func() {
				// In case of hard timeout, a panic may occur.
				// This deferred function allows us to recover from such scenarios.
				defer func() {
					if r := recover(); r != nil {
						logger.Debug(fmt.Sprintf("recovering from a panic (possible cause being a hard timeout): %s", r))
					}
				}()

				// Call the next middleware in the chain.
				errChan <- next(c)
			}()

			select {
			case err := <-errChan:
				return err
			case <-hardTimeoutCtx.Done():
				logger.Debug("hard timeout as the route handler did not timeout as expected")

				return fmt.Errorf("hard timeout: %w", hardTimeoutCtx.Err())
			}
		}
	}
}