diff --git a/server/channels/app/file.go b/server/channels/app/file.go index d63f6c9e44b..faa17021681 100644 --- a/server/channels/app/file.go +++ b/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) } diff --git a/server/channels/jobs/extract_content/worker.go b/server/channels/jobs/extract_content/worker.go index 1a085b0122f..1cf683ac4e7 100644 --- a/server/channels/jobs/extract_content/worker.go +++ b/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)) diff --git a/server/platform/services/docextractor/archive.go b/server/platform/services/docextractor/archive.go index c66d3d65e28..f80e777e065 100644 --- a/server/platform/services/docextractor/archive.go +++ b/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 diff --git a/server/platform/services/docextractor/archive_test.go b/server/platform/services/docextractor/archive_test.go index b1eecb36c09..778a9cfe1ef 100644 --- a/server/platform/services/docextractor/archive_test.go +++ b/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) + }) + } +} diff --git a/server/platform/services/docextractor/combine.go b/server/platform/services/docextractor/combine.go index 6b0708d1304..16cf2cf69a5 100644 --- a/server/platform/services/docextractor/combine.go +++ b/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