Merge branch '320-improve-image-scaler-logs' into 'master'

Consistent logging in image resizer module

Closes #320

See merge request gitlab-org/gitlab-workhorse!652

changelogs/unreleased/320-improve-image-scaler-logs.yml

+---
+title: Improve logging for image scaler
+merge_request: 652
+author:
+type: other

internal/helper/helpers.go

@@ -37,10 +37,19 @@ func CaptureAndFail(w http.ResponseWriter, r *http.Request, err error, msg strin
 	LogError(r, err)
 }
 
+func CaptureAndFailWithFields(w http.ResponseWriter, r *http.Request, err error, msg string, code int, fields log.Fields) {
+	http.Error(w, msg, code)
+	LogErrorWithFields(r, err, fields)
+}
+
 func Fail500(w http.ResponseWriter, r *http.Request, err error) {
 	CaptureAndFail(w, r, err, "Internal server error", http.StatusInternalServerError)
 }
 
+func Fail500WithFields(w http.ResponseWriter, r *http.Request, err error, fields log.Fields) {
+	CaptureAndFailWithFields(w, r, err, "Internal server error", http.StatusInternalServerError, fields)
+}
+
 func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
 	CaptureAndFail(w, r, err, "Request Entity Too Large", http.StatusRequestEntityTooLarge)
 }

internal/imageresizer/image_resizer.go

@@ -17,8 +17,10 @@ import (
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
+
 	"gitlab.com/gitlab-org/labkit/correlation"
 	"gitlab.com/gitlab-org/labkit/log"
+	"gitlab.com/gitlab-org/labkit/mask"
 	"gitlab.com/gitlab-org/labkit/tracing"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
@@ -50,10 +52,18 @@ type imageFile struct {
 	lastModified  time.Time
 }
 
+// Carries information about how the scaler succeeded or failed.
+type resizeOutcome struct {
+	bytesWritten     int64
+	originalFileSize int64
+	status           resizeStatus
+	err              error
+}
+
 const (
 	statusSuccess        = "success"              // a rescaled image was served
 	statusClientCache    = "success-client-cache" // scaling was skipped because client cache was fresh
-	statusScalingFailure = "scaling-failed"       // scaling failed but the original image was served
+	statusServedOriginal = "served-original"      // scaling failed but the original image was served
 	statusRequestFailure = "request-failed"       // no image was served
 	statusUnknown        = "unknown"              // indicates an unhandled status case
 )
@@ -82,6 +92,7 @@ var httpClient = &http.Client{
 const (
 	namespace = "gitlab_workhorse"
 	subsystem = "image_resize"
+	logSystem = "imageresizer"
 )
 
 var (
@@ -160,91 +171,72 @@ func NewResizer(cfg config.Config) *Resizer {
 // Inject forks into a dedicated scaler process to resize an image identified by path or URL
 // and streams the resized image back to the client
 func (r *Resizer) Inject(w http.ResponseWriter, req *http.Request, paramsData string) {
-	var status resizeStatus = statusUnknown
+	var outcome = resizeOutcome{status: statusUnknown, originalFileSize: 0, bytesWritten: 0}
+	start := time.Now()
+	params, err := r.unpackParameters(paramsData)
+
 	defer func() {
-		imageResizeRequests.WithLabelValues(status).Inc()
+		imageResizeRequests.WithLabelValues(outcome.status).Inc()
+		handleOutcome(w, req, start, params, &outcome)
 	}()
 
-	start := time.Now()
-	logger := log.ContextLogger(req.Context())
-	params, err := r.unpackParameters(paramsData)
 	if err != nil {
 		// This means the response header coming from Rails was malformed; there is no way
 		// to sensibly recover from this other than failing fast
-		status = statusRequestFailure
-		helper.Fail500(w, req, fmt.Errorf("ImageResizer: Failed reading image resize params: %v", err))
+		outcome.error(fmt.Errorf("read image resize params: %v", err))
 		return
 	}
 
 	imageFile, err := openSourceImage(params.Location)
 	if err != nil {
 		// This means we cannot even read the input image; fail fast.
-		status = statusRequestFailure
-		helper.Fail500(w, req, fmt.Errorf("ImageResizer: Failed opening image data stream: %v", err))
+		outcome.error(fmt.Errorf("open image data stream: %v", err))
 		return
 	}
 	defer imageFile.reader.Close()
 
-	logFields := func(bytesWritten int64) *log.Fields {
-		return &log.Fields{
-			"bytes_written":     bytesWritten,
-			"duration_s":        time.Since(start).Seconds(),
-			"target_width":      params.Width,
-			"content_type":      params.ContentType,
-			"original_filesize": imageFile.contentLength,
-		}
-	}
+	outcome.originalFileSize = imageFile.contentLength
 
 	setLastModified(w, imageFile.lastModified)
 	// If the original file has not changed, then any cached resized versions have not changed either.
 	if checkNotModified(req, imageFile.lastModified) {
-		status = statusClientCache
-		logger.WithFields(*logFields(0)).Printf("ImageResizer: Use cached image")
 		writeNotModified(w)
+		outcome.ok(statusClientCache)
 		return
 	}
 
 	// We first attempt to rescale the image; if this should fail for any reason, imageReader
 	// will point to the original image, i.e. we render it unchanged.
-	imageReader, resizeCmd, err := r.tryResizeImage(req, imageFile, logger.Writer(), params, r.Config.ImageResizerConfig)
+	imageReader, resizeCmd, err := r.tryResizeImage(req, imageFile, params, r.Config.ImageResizerConfig)
 	if err != nil {
 		// Something failed, but we can still write out the original image, so don't return early.
-		helper.LogErrorWithFields(req, err, *logFields(0))
+		// We need to log this separately since the subsequent steps might add other failures.
+		helper.LogErrorWithFields(req, err, *logFields(start, params, &outcome))
 	}
 	defer helper.CleanUpProcessGroup(resizeCmd)
 
 	w.Header().Del("Content-Length")
-	bytesWritten, err := serveImage(imageReader, w, resizeCmd)
+	outcome.bytesWritten, err = serveImage(imageReader, w, resizeCmd)
 
 	// We failed serving image data; this is a hard failure.
 	if err != nil {
-		status = statusRequestFailure
-		if bytesWritten <= 0 {
-			helper.Fail500(w, req, err)
-		} else {
-			helper.LogErrorWithFields(req, err, *logFields(bytesWritten))
-		}
+		outcome.error(err)
 		return
 	}
 
 	// This means we served the original image because rescaling failed; this is a soft failure
 	if resizeCmd == nil {
-		status = statusScalingFailure
-		logger.WithFields(*logFields(bytesWritten)).Printf("ImageResizer: Served original")
+		outcome.ok(statusServedOriginal)
 		return
 	}
 
 	widthLabelVal := strconv.Itoa(int(params.Width))
 	imageResizeDurations.WithLabelValues(params.ContentType, widthLabelVal).Observe(time.Since(start).Seconds())
 
-	logger.WithFields(*logFields(bytesWritten)).Printf("ImageResizer: Success")
-
-	status = statusSuccess
+	outcome.ok(statusSuccess)
 }
 
 // Streams image data from the given reader to the given writer and returns the number of bytes written.
-// Errors are either served to the caller or merely logged, depending on whether any image data had
-// already been transmitted or not.
 func serveImage(r io.Reader, w io.Writer, resizeCmd *exec.Cmd) (int64, error) {
 	bytesWritten, err := io.Copy(w, r)
 	if err != nil {
@@ -252,7 +244,13 @@ func serveImage(r io.Reader, w io.Writer, resizeCmd *exec.Cmd) (int64, error) {
 	}
 
 	if resizeCmd != nil {
-		return bytesWritten, resizeCmd.Wait()
+		// If a scaler process had been forked, wait for the command to finish.
+		if err = resizeCmd.Wait(); err != nil {
+			// err will be an ExitError; this is not useful beyond knowing the exit code since anything
+			// interesting has been written to stderr, so we turn that into an error we can return.
+			stdErr := resizeCmd.Stderr.(*strings.Builder)
+			return bytesWritten, fmt.Errorf(stdErr.String())
+		}
 	}
 
 	return bytesWritten, nil
@@ -265,24 +263,24 @@ func (r *Resizer) unpackParameters(paramsData string) (*resizeParams, error) {
 	}
 
 	if params.Location == "" {
-		return nil, fmt.Errorf("ImageResizer: Location is empty")
+		return nil, fmt.Errorf("'Location' not set")
 	}
 
 	if params.ContentType == "" {
-		return nil, fmt.Errorf("ImageResizer: ContentType must be set")
+		return nil, fmt.Errorf("'ContentType' must be set")
 	}
 
 	return &params, nil
 }
 
 // Attempts to rescale the given image data, or in case of errors, falls back to the original image.
-func (r *Resizer) tryResizeImage(req *http.Request, f *imageFile, errorWriter io.Writer, params *resizeParams, cfg config.ImageResizerConfig) (io.Reader, *exec.Cmd, error) {
+func (r *Resizer) tryResizeImage(req *http.Request, f *imageFile, params *resizeParams, cfg config.ImageResizerConfig) (io.Reader, *exec.Cmd, error) {
 	if f.contentLength > int64(cfg.MaxFilesize) {
-		return f.reader, nil, fmt.Errorf("ImageResizer: %db exceeds maximum file size of %db", f.contentLength, cfg.MaxFilesize)
+		return f.reader, nil, fmt.Errorf("%d bytes exceeds maximum file size of %d bytes", f.contentLength, cfg.MaxFilesize)
 	}
 
 	if !r.numScalerProcs.tryIncrement(int32(cfg.MaxScalerProcs)) {
-		return f.reader, nil, fmt.Errorf("ImageResizer: too many running scaler processes (%d / %d)", r.numScalerProcs.n, cfg.MaxScalerProcs)
+		return f.reader, nil, fmt.Errorf("too many running scaler processes (%d / %d)", r.numScalerProcs.n, cfg.MaxScalerProcs)
 	}
 
 	ctx := req.Context()
@@ -295,26 +293,27 @@ func (r *Resizer) tryResizeImage(req *http.Request, f *imageFile, errorWriter io
 	bufferSize := int(math.Min(maxMagicLen, float64(f.contentLength)))
 	buffered := bufio.NewReaderSize(f.reader, bufferSize)
 
-	data, err := buffered.Peek(bufferSize)
+	headerBytes, err := buffered.Peek(bufferSize)
 	if err != nil {
-		return buffered, nil, fmt.Errorf("ImageResizer: failed to peek into data: %v", err)
+		return buffered, nil, fmt.Errorf("peek stream: %v", err)
 	}
 
-	if string(data) != pngMagic && string(data[0:2]) != jpegMagic {
-		return buffered, nil, fmt.Errorf("ImageResizer: format is prohibited")
+	// Check magic bytes to identify file type.
+	if string(headerBytes) != pngMagic && string(headerBytes[0:2]) != jpegMagic {
+		return buffered, nil, fmt.Errorf("unrecognized file signature: %v", headerBytes)
 	}
 
-	resizeCmd, resizedImageReader, err := startResizeImageCommand(ctx, buffered, errorWriter, params)
+	resizeCmd, resizedImageReader, err := startResizeImageCommand(ctx, buffered, params)
 	if err != nil {
-		return buffered, nil, fmt.Errorf("ImageResizer: failed forking into scaler process: %w", err)
+		return buffered, nil, fmt.Errorf("fork into scaler process: %w", err)
 	}
 	return resizedImageReader, resizeCmd, nil
 }
 
-func startResizeImageCommand(ctx context.Context, imageReader io.Reader, errorWriter io.Writer, params *resizeParams) (*exec.Cmd, io.ReadCloser, error) {
+func startResizeImageCommand(ctx context.Context, imageReader io.Reader, params *resizeParams) (*exec.Cmd, io.ReadCloser, error) {
 	cmd := exec.CommandContext(ctx, "gitlab-resize-image")
 	cmd.Stdin = imageReader
-	cmd.Stderr = errorWriter
+	cmd.Stderr = &strings.Builder{}
 	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
 	cmd.Env = []string{
 		"GL_RESIZE_IMAGE_WIDTH=" + strconv.Itoa(int(params.Width)),
@@ -362,8 +361,7 @@ func openFromURL(location string) (*imageFile, error) {
 		return &imageFile{res.Body, res.ContentLength, lastModified}, nil
 	default:
 		res.Body.Close()
-		return nil, fmt.Errorf("unexpected upstream response for %q: %d %s",
-			location, res.StatusCode, res.Status)
+		return nil, fmt.Errorf("stream data from %q: %d %s", location, res.StatusCode, res.Status)
 	}
 }
 
@@ -400,3 +398,51 @@ func (c *processCounter) decrement() {
 	atomic.AddInt32(&c.n, -1)
 	imageResizeProcesses.Set(float64(c.n))
 }
+
+func (o *resizeOutcome) ok(status resizeStatus) {
+	o.status = status
+	o.err = nil
+}
+
+func (o *resizeOutcome) error(err error) {
+	o.status = statusRequestFailure
+	o.err = err
+}
+
+func logFields(startTime time.Time, params *resizeParams, outcome *resizeOutcome) *log.Fields {
+	var targetWidth, contentType string
+	if params != nil {
+		targetWidth = fmt.Sprint(params.Width)
+		contentType = fmt.Sprint(params.ContentType)
+	}
+	return &log.Fields{
+		"subsystem":                      logSystem,
+		"written_bytes":                  outcome.bytesWritten,
+		"duration_s":                     time.Since(startTime).Seconds(),
+		logSystem + ".status":            outcome.status,
+		logSystem + ".target_width":      targetWidth,
+		logSystem + ".content_type":      contentType,
+		logSystem + ".original_filesize": outcome.originalFileSize,
+	}
+}
+
+func handleOutcome(w http.ResponseWriter, req *http.Request, startTime time.Time, params *resizeParams, outcome *resizeOutcome) {
+	logger := log.ContextLogger(req.Context())
+	fields := *logFields(startTime, params, outcome)
+
+	switch outcome.status {
+	case statusRequestFailure:
+		if outcome.bytesWritten <= 0 {
+			helper.Fail500WithFields(w, req, outcome.err, fields)
+		} else {
+			helper.LogErrorWithFields(req, outcome.err, fields)
+		}
+	default:
+		logger.WithFields(fields).WithFields(
+			log.Fields{
+				"method": req.Method,
+				"uri":    mask.URL(req.RequestURI),
+			},
+		).Printf(outcome.status)
+	}
+}