Log file IDs instead of filenames during file upload and content extraction (#37987)

server/channels/app/file.go

@@ -808,7 +808,6 @@ func (a *App) UploadFileX(rctx request.CTX, channelID, name string, input io.Rea
 	}
 
 	rctx = rctx.WithLogFields(
-		mlog.String("file_name", name),
 		mlog.String("channel_id", channelID),
 		mlog.String("user_id", t.UserId),
 	)
@@ -822,6 +821,10 @@ func (a *App) UploadFileX(rctx request.CTX, channelID, name string, input io.Rea
 
 	t.init(a)
 
+	rctx = rctx.WithLogFields(
+		mlog.String("file_info_id", t.fileinfo.Id),
+	)
+
 	var aerr *model.AppError
 	if !t.Raw && t.fileinfo.IsImage() {
 		aerr = t.preprocessImage()
@@ -879,10 +882,10 @@ func (a *App) UploadFileX(rctx request.CTX, channelID, name string, input io.Rea
 		if !a.Srv().GoExtraction(func() {
 			err := a.ExtractContentFromFileInfo(rctx, &infoCopy)
 			if err != nil {
-				rctx.Logger().Error("Failed to extract file content", mlog.Err(err), mlog.String("file_info_id", infoCopy.Id))
+				rctx.Logger().Error("Failed to extract file content", mlog.Err(err))
 			}
 		}) {
-			rctx.Logger().Warn("Content extraction queue is full, skipping inline extraction; this file's content will not be searchable until the scheduled content extraction catch-up job runs or an admin runs a content extraction job (e.g. mmctl extract)", mlog.String("file_info_id", infoCopy.Id))
+			rctx.Logger().Warn("Content extraction queue is full, skipping inline extraction; this file's content will not be searchable until the scheduled content extraction catch-up job runs or an admin runs a content extraction job (e.g. mmctl extract)")
 		}
 	}
 
@@ -1713,6 +1716,9 @@ func (a *App) ExtractContentFromFileInfo(rctx request.CTX, fileInfo *model.FileI
 		return nil
 	}
 
+	logger := rctx.Logger().With(mlog.String("file_info_id", fileInfo.Id))
+	logger.Debug("Extracting content from file", mlog.String("extension", fileInfo.Extension))
+
 	file, aerr := a.FileReader(fileInfo.Path)
 	if aerr != nil {
 		return errors.Wrap(aerr, "failed to open file for extract file content")
@@ -1721,7 +1727,7 @@ func (a *App) ExtractContentFromFileInfo(rctx request.CTX, fileInfo *model.FileI
 	// ReaderCloser: with a timeout configured, extraction may continue on a
 	// detached goroutine after Extract returns, so closing the file here would
 	// race with that goroutine still reading it.
-	text, err := docextractor.Extract(rctx.Logger(), fileInfo.Name, file, docextractor.ExtractSettings{
+	text, err := docextractor.Extract(logger, fileInfo.Name, file, docextractor.ExtractSettings{
 		Ctx:              rctx.Context(),
 		ArchiveRecursion: *a.Config().FileSettings.ArchiveRecursion,
 		MaxFileSize:      *a.Config().FileSettings.MaxFileSize,
@@ -1740,7 +1746,7 @@ func (a *App) ExtractContentFromFileInfo(rctx request.CTX, fileInfo *model.FileI
 		}
 		reloadFileInfo, storeErr := a.Srv().Store().FileInfo().Get(fileInfo.Id)
 		if storeErr != nil {
-			rctx.Logger().Warn("Failed to invalidate the fileInfo cache.", mlog.Err(storeErr), mlog.String("file_info_id", fileInfo.Id))
+			logger.Warn("Failed to invalidate the fileInfo cache.", mlog.Err(storeErr))
 		} else {
 			a.Srv().Store().FileInfo().InvalidateFileInfosForPostCache(reloadFileInfo.PostId, false)
 		}

server/channels/jobs/extract_content/worker.go

@@ -74,8 +74,6 @@ func runCatchupExtraction(logger mlog.LoggerIFace, job *model.Job, jobServer *jo
 				continue
 			}
 
-			logger.Debug("Extracting file", mlog.String("filename", fileInfo.Name), mlog.String("filepath", fileInfo.Path))
-
 			err = app.ExtractContentFromFileInfo(request.EmptyContext(logger), fileInfo)
 			if err != nil {
 				logger.Warn("Failed to extract file content", mlog.Err(err), mlog.String("file_info_id", fileInfo.Id))
@@ -135,8 +133,6 @@ func runRangeExtraction(logger mlog.LoggerIFace, job *model.Job, jobServer *jobs
 		}
 		for _, fileInfo := range fileInfos {
 			if !ignoredFiles[fileInfo.Extension] {
-				logger.Debug("Extracting file", mlog.String("filename", fileInfo.Name), mlog.String("filepath", fileInfo.Path))
-
 				err = app.ExtractContentFromFileInfo(request.EmptyContext(logger), fileInfo)
 				if err != nil {
 					logger.Warn("Failed to extract file content", mlog.Err(err), mlog.String("file_info_id", fileInfo.Id))

server/platform/services/docextractor/archive.go

@@ -100,14 +100,14 @@ func (ae *archiveExtractor) Extract(ctx context.Context, name string, r io.ReadS
 
 			data, err := io.ReadAll(reader)
 			if err != nil {
-				return fmt.Errorf("error reading archive entry %s: %w", path, err)
+				return fmt.Errorf("error reading archive entry: %w", err)
 			}
 
 			subtext, extractErr := ae.SubExtractor.Extract(ctx, filename, bytes.NewReader(data), maxFileSize)
 			if extractErr == nil {
 				text.WriteString(subtext + " ")
 			} else if errors.Is(extractErr, context.Canceled) || errors.Is(extractErr, context.DeadlineExceeded) {
-				return fmt.Errorf("error extracting %q: %w", filename, extractErr)
+				return fmt.Errorf("error extracting archive entry: %w", extractErr)
 			}
 		}
 		return nil

server/platform/services/docextractor/archive_test.go

@@ -4,8 +4,11 @@
 package docextractor
 
 import (
+	"archive/zip"
 	"bytes"
 	"context"
+	"io"
+	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -51,3 +54,64 @@ func TestArchiveExtractorSkips7zip(t *testing.T) {
 		assert.Error(t, err) // fails to extract as any valid archive format
 	})
 }
+
+// contextErrorExtractor fails every extraction with the given context error.
+type contextErrorExtractor struct {
+	err error
+}
+
+func (ce *contextErrorExtractor) Name() string {
+	return "contextErrorExtractor"
+}
+
+func (ce *contextErrorExtractor) Match(filename string) bool {
+	return true
+}
+
+func (ce *contextErrorExtractor) Extract(_ context.Context, _ string, _ io.ReadSeeker, _ int64) (string, error) {
+	return "", ce.err
+}
+
+func TestArchiveExtractorErrorOmitsEntryName(t *testing.T) {
+	// The entry name is transformed before reaching the nested extraction error
+	// (separators become spaces), so assert on the stem token as well: it
+	// survives that transformation and would appear in either leaky error.
+	const entryName = "confidential-customer-list.txt"
+	const entryStem = "confidential"
+
+	var archive bytes.Buffer
+	zw := zip.NewWriter(&archive)
+	entry, err := zw.Create(entryName)
+	require.NoError(t, err)
+	_, err = entry.Write([]byte(strings.Repeat("a", 1024)))
+	require.NoError(t, err)
+	require.NoError(t, zw.Close())
+
+	requireNoEntryName := func(t *testing.T, err error) {
+		t.Helper()
+		require.Error(t, err)
+		assert.NotContains(t, err.Error(), entryName)
+		assert.NotContains(t, err.Error(), entryStem)
+	}
+
+	t.Run("entry read failure", func(t *testing.T) {
+		ae := &archiveExtractor{SubExtractor: &plainExtractor{}}
+
+		// A maxFileSize below the entry size fails the entry read.
+		_, err := ae.Extract(context.Background(), "archive.zip", bytes.NewReader(archive.Bytes()), 8)
+		requireNoEntryName(t, err)
+	})
+
+	for name, contextErr := range map[string]error{
+		"cancelled":         context.Canceled,
+		"deadline exceeded": context.DeadlineExceeded,
+	} {
+		t.Run("nested extraction "+name, func(t *testing.T) {
+			ae := &archiveExtractor{SubExtractor: &contextErrorExtractor{err: contextErr}}
+
+			_, err := ae.Extract(context.Background(), "archive.zip", bytes.NewReader(archive.Bytes()), 0)
+			requireNoEntryName(t, err)
+			assert.ErrorIs(t, err, contextErr)
+		})
+	}
+}

server/platform/services/docextractor/combine.go

@@ -44,7 +44,8 @@ func (ce *combineExtractor) Extract(ctx context.Context, filename string, r io.R
 				if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) {
 					return "", err
 				}
-				ce.logger.Warn("Unable to extract file content", mlog.String("file_name", filename), mlog.String("extractor", extractor.Name()), mlog.Err(err))
+
+				ce.logger.Warn("Unable to extract file content", mlog.String("extractor", extractor.Name()), mlog.Err(err))
 				continue
 			}
 			return text, nil