diff --git a/cmd/msgvault/cmd/attachment_maintenance.go b/cmd/msgvault/cmd/attachment_maintenance.go index 10359d5ad6..c3e5b5c510 100644 --- a/cmd/msgvault/cmd/attachment_maintenance.go +++ b/cmd/msgvault/cmd/attachment_maintenance.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "log/slog" + "strings" "sync/atomic" "time" @@ -25,9 +26,10 @@ const ( automaticAttachmentMaxRuntime = time.Minute attachmentMaintenanceJob = "attachment-maintenance" attachmentMaintenanceCron = "17 3 * * *" - // attachmentPackJob packs blobs that scheduled syncs left loose. A pass - // re-reads the whole pack catalog, so it runs a few times a day rather - // than after every sync. Bounded follow-ups drain any remaining backlog. + // attachmentPackJob packs loose blobs in bounded background passes. It + // runs on its schedule and whenever a manual ingest sent to the daemon + // succeeds, after that request has returned. Follow-ups drain a loose + // backlog larger than one pass's byte budget. attachmentPackJob = "attachment-pack" attachmentPackCron = "41 */6 * * *" importMboxCommand = "import-mbox" @@ -44,9 +46,16 @@ type attachmentMaintenance struct { logger *slog.Logger packCreationEnabled bool attachmentsDir string - // packPending records that a scheduled sync wrote loose blobs that no - // pack pass has drained yet. Startup requests one scan of existing blobs. + // packPending records that an ingest wrote loose blobs that no pack pass + // has drained yet. Startup requests one scan of existing blobs. packPending atomic.Bool + // requestPackJob asks the daemon scheduler for a background + // attachment-pack run, and packJobLastError reports the scheduler's + // record of that job's last failure. registerAttachmentPackJob sets both + // before the daemon serves requests; without them a pending pass waits + // for the job's schedule. + requestPackJob func() error + packJobLastError func() string } func newAttachmentMaintenance( @@ -126,10 +135,10 @@ func (m *attachmentMaintenance) unpack(ctx context.Context) (packstore.UnpackSta return stats, nil } -// runAutomaticPack performs one bounded maintenance pass. Errors remain -// visible to schedulers, while callers following a successful ingest can log -// or stream the warning and deliberately preserve the ingest result. -func (m *attachmentMaintenance) runAutomaticPack(ctx context.Context, emitWarning func(string) error) error { +// runAutomaticPack performs one pack pass with the automatic byte budget. +// Scheduled callers bound its verification work and runtime; errors remain +// visible to them. +func (m *attachmentMaintenance) runAutomaticPack(ctx context.Context) error { if !m.packCreationEnabled { m.log().Debug("automatic attachment packing disabled") return nil @@ -152,17 +161,9 @@ func (m *attachmentMaintenance) runAutomaticPack(ctx context.Context, emitWarnin } m.logAutomaticPackSummary("automatic attachment maintenance progress", stats, duration) - const retry = "run `msgvault pack-attachments` to retry" m.log().Warn("automatic attachment maintenance failed", "error", err, - "retry", retry) - if emitWarning != nil { - warning := fmt.Sprintf("Automatic attachment maintenance failed: %v; %s.\n", err, retry) - if emitErr := emitWarning(warning); emitErr != nil { - m.log().Warn("failed to emit automatic attachment maintenance warning", - "error", emitErr) - } - } + "retry", "run `msgvault pack-attachments` to retry") return err } @@ -241,41 +242,47 @@ func (m *attachmentMaintenance) logAutomaticRepackSummary(message string, stats "budget_exhausted", stats.BudgetExhausted) } -// runScheduledPack bounds existing-blob verification as well as new pack bytes. -func (m *attachmentMaintenance) runScheduledPack(ctx context.Context) error { +// runScheduledPack performs one pass that packs new loose blobs within the +// byte budget and verifies only the next window of existing packed blobs. +// The pass still lists every referenced hash and checks every pack file, so +// part of its cost grows with the archive. A pass that stops at its byte +// budget leaves packPending set. verifyMore reports that the durable +// verification cursor has further windows. +func (m *attachmentMaintenance) runScheduledPack(ctx context.Context) (verifyMore bool, err error) { if !m.packCreationEnabled { - return nil + return false, nil } packCtx, pass, err := m.store.BeginPackVerification(ctx, 128, 32<<20) if err != nil { - return err + return false, err } - if err := m.runAutomaticPack(packCtx, nil); err != nil { - return err + if err := m.runAutomaticPack(packCtx); err != nil { + return false, err } more, err := m.store.FinishPackVerification(ctx, pass) if err != nil { - return err + return false, err } if more { // A completed verification cycle restarts on the next request. Only an // unfinished window provides a resume point for a budgeted follow-up. jobctx.RecordProgress(ctx) - m.markPackPending() } - return nil + return more, nil } -// daily runs the two bounded phases in order. A failed pack phase stops the -// job so the scheduler records the failure instead of obscuring it with a -// second maintenance result. +// daily runs the two bounded phases in order. Follow-ups finish the loose +// backlog and the whole verification cycle before the repack phase. A failed +// pack phase stops the job so the scheduler records the failure instead of +// obscuring it with a second maintenance result. func (m *attachmentMaintenance) daily(ctx context.Context) error { m.packPending.Store(false) - if err := m.runScheduledPack(ctx); err != nil { + verifyMore, err := m.runScheduledPack(ctx) + if err != nil { m.markPackPending() return err } - if m.packPending.Load() { + if verifyMore || m.packPending.Load() { return scheduler.ErrReschedule } return m.runAutomaticRepack(ctx, nil) @@ -288,14 +295,17 @@ func (m *attachmentMaintenance) markPackPending() { } } -// runPendingPack runs one automatic pack pass when a scheduled sync left new -// loose blobs since the last pass. A failed pass leaves the request pending; -// an exhausted byte budget queues another pass behind waiting work. +// runPendingPack runs one automatic pack pass when an ingest left new loose +// blobs since the last pass. A failed pass leaves the request pending; an +// exhausted byte budget queues another pass behind waiting work. Each pass +// advances verification by one window but does not chain a whole +// verification cycle: on a large archive that is hundreds of passes, and the +// daily attachment-maintenance job completes cycles. func (m *attachmentMaintenance) runPendingPack(ctx context.Context) error { if m == nil || !m.packPending.Swap(false) { return nil } - if err := m.runScheduledPack(ctx); err != nil { + if _, err := m.runScheduledPack(ctx); err != nil { m.packPending.Store(true) return err } @@ -305,6 +315,25 @@ func (m *attachmentMaintenance) runPendingPack(ctx context.Context) error { return nil } +// requestPack records that a successful manual ingest may have left loose +// blobs and asks the attachment-pack job to pack them. It never waits: the +// job takes the operation gate after the ingest's request releases it, runs +// under the job's runtime limit, and counts as daemon activity while it +// waits and runs. Without a registered job the request stays pending. +func (m *attachmentMaintenance) requestPack() { + if m == nil || !m.packCreationEnabled { + return + } + m.markPackPending() + if m.requestPackJob == nil { + return + } + if err := m.requestPackJob(); err != nil { + m.log().Info("background attachment packing not started; new blobs stay pending", + "job", attachmentPackJob, "error", err) + } +} + // looseBlobWrites reports the in-process count of loose blobs created under // this maintenance's attachments directory. func (m *attachmentMaintenance) looseBlobWrites() int64 { @@ -321,21 +350,41 @@ func (m *attachmentMaintenance) log() *slog.Logger { return slog.Default() } -// runAfterSuccessfulAttachmentIngest runs bounded maintenance only after a -// successful ingest. Maintenance and warning-stream failures are best-effort: -// neither may replace the successful ingest result. +// reportPackFailure tells the user of a manual ingest that the previous +// background pack pass failed. A background pass has no request to report +// to, so the next ingest carries a one-line notice. Notices are +// best-effort and never change the ingest result. +func (m *attachmentMaintenance) reportPackFailure(emitNotice func(string) error) { + if m == nil || emitNotice == nil || m.packJobLastError == nil { + return + } + lastErr := strings.TrimSpace(m.packJobLastError()) + if lastErr == "" { + return + } + notice := fmt.Sprintf( + "Warning: the last background attachment packing pass failed: %s; run `msgvault pack-attachments` to retry.\n", + strings.Join(strings.Fields(lastErr), " ")) + if err := emitNotice(notice); err != nil { + m.log().Warn("failed to emit attachment packing notice", "error", err) + } +} + +// runAfterSuccessfulAttachmentIngest requests background packing only after +// a successful ingest. The caller's request returns as soon as the ingest +// does; packing can neither delay nor replace the ingest result. A failure +// of the previous background pass is reported through emitNotice. func runAfterSuccessfulAttachmentIngest( ctx context.Context, maintenance *attachmentMaintenance, ingest func(context.Context) error, - emitWarning func(string) error, + emitNotice func(string) error, ) error { if err := runWithAttachmentMutation(ctx, maintenance, ingest); err != nil { return err } - if maintenance != nil { - _ = maintenance.runAutomaticPack(ctx, emitWarning) - } + maintenance.reportPackFailure(emitNotice) + maintenance.requestPack() return nil } @@ -406,15 +455,29 @@ func registerAttachmentMaintenanceJob(sched *scheduler.Scheduler, maintenance *a } func registerAttachmentPackJob(sched *scheduler.Scheduler, maintenance *attachmentMaintenance) error { - // Recheck the catalog on the first tick after startup. In-memory write + // Recheck the catalog on the first pass after startup. In-memory write // counts cannot tell us what a previous daemon left loose. maintenance.markPackPending() - return sched.AddJob(scheduler.Job{ + if err := sched.AddJob(scheduler.Job{ Name: attachmentPackJob, MaxRuntime: automaticAttachmentMaxRuntime, Schedule: attachmentPackCron, Run: maintenance.runPendingPack, - }) + }); err != nil { + return err + } + // A daemon started on demand may idle out long before the next cron + // tick, so ingests start the job themselves and report its failures. + maintenance.requestPackJob = func() error { return sched.RequestJob(attachmentPackJob) } + maintenance.packJobLastError = func() string { + for _, status := range sched.JobStatus() { + if status.Name == attachmentPackJob { + return status.LastError + } + } + return "" + } + return nil } func registerScheduledBeeperJob( diff --git a/cmd/msgvault/cmd/attachment_maintenance_test.go b/cmd/msgvault/cmd/attachment_maintenance_test.go index 712779ab9c..5e430c21ee 100644 --- a/cmd/msgvault/cmd/attachment_maintenance_test.go +++ b/cmd/msgvault/cmd/attachment_maintenance_test.go @@ -15,6 +15,7 @@ import ( "path/filepath" "strings" "testing" + "testing/synctest" "time" "github.com/stretchr/testify/assert" @@ -22,6 +23,7 @@ import ( "go.kenn.io/kit/pack" "go.kenn.io/kit/packstore" + "go.kenn.io/msgvault/internal/api" "go.kenn.io/msgvault/internal/attachmentstore" "go.kenn.io/msgvault/internal/export" "go.kenn.io/msgvault/internal/jobctx" @@ -155,19 +157,14 @@ func TestAutomaticAttachmentMaintenancePacksBoundedAndLogsCompleteStats(t *testi f := newAttachmentMaintenanceFixture(t) content := []byte("automatic attachment maintenance payload") hash := f.addLoose(content) - warnings := 0 - err := f.maintenance.runAutomaticPack(context.Background(), func(string) error { - warnings++ - return nil - }) + err := f.maintenance.runAutomaticPack(context.Background()) require.NoError(err, "runAutomaticPack") gotAutomaticAttachmentBytes := automaticAttachmentBytes assert.Equal(wantAutomaticAttachmentBytes, gotAutomaticAttachmentBytes) assert.Equal("attachment-maintenance", attachmentMaintenanceJob) assert.Equal("17 3 * * *", attachmentMaintenanceCron) - assert.Zero(warnings, "successful automatic packing must not emit CLI output") require.NotNil(f.packedEntry(hash), "loose attachment must be packed") assert.Equal(content, f.readBlob(hash), "packed attachment stays readable") @@ -205,7 +202,7 @@ func TestLooseAttachmentModeSkipsAutomaticPackingAndRejectsPackCreation(t *testi f.maintenance.packCreationEnabled = false hash := f.addLoose([]byte("remain loose when attachment packing is disabled")) - err := f.maintenance.runAutomaticPack(context.Background(), nil) + err := f.maintenance.runAutomaticPack(context.Background()) require.NoError(err) assert.Nil(f.packedEntry(hash)) assert.Contains(f.logs.String(), "automatic attachment packing disabled") @@ -225,38 +222,26 @@ func TestAutomaticAttachmentMaintenanceCancellationIsInformational(t *testing.T) f := newAttachmentMaintenanceFixture(t) ctx, cancel := context.WithCancel(context.Background()) cancel() - warnings := 0 - err := f.maintenance.runAutomaticPack(ctx, func(string) error { - warnings++ - return nil - }) + err := f.maintenance.runAutomaticPack(ctx) require.ErrorIs(err, context.Canceled) - assert.Zero(warnings) assert.Contains(f.logs.String(), "level=INFO msg=\"automatic attachment maintenance canceled\"") assert.NotContains(f.logs.String(), "level=WARN") } -func TestAutomaticAttachmentMaintenanceFailureWarnsWithoutReplacingIngestSuccess(t *testing.T) { +func TestBackgroundPackFailureLogsProgressAndStaysPending(t *testing.T) { require := require.New(t) assert := assert.New(t) maintenance, logs := newFailingAttachmentMaintenance(t) - var warning string - err := runAfterSuccessfulAttachmentIngest( - context.Background(), - maintenance, - func(context.Context) error { return nil }, - func(message string) error { - warning = message - return nil - }, - ) + require.NoError(runAfterSuccessfulAttachmentIngest( + context.Background(), maintenance, func(context.Context) error { return nil }, nil, + ), "a later maintenance failure cannot reach the ingest result") + require.Error(maintenance.runPendingPack(context.Background()), "the job records the failure") + assert.True(maintenance.packPending.Load(), "a failed pass leaves its work pending") - require.NoError(err, "maintenance failure must preserve successful ingest") - assert.Contains(warning, "pack-attachments") - assert.Contains(warning, "retry") + require.Error(maintenance.runAutomaticPack(context.Background())) logOutput := logs.String() progressAt := strings.Index(logOutput, "level=INFO msg=\"automatic attachment maintenance progress\"") warnAt := strings.Index(logOutput, "level=WARN msg=\"automatic attachment maintenance failed\"") @@ -268,24 +253,6 @@ func TestAutomaticAttachmentMaintenanceFailureWarnsWithoutReplacingIngestSuccess assert.Contains(logOutput, "pack-attachments", "log names the explicit retry command") } -func TestAutomaticAttachmentMaintenanceWarningFailurePreservesIngestSuccess(t *testing.T) { - require := require.New(t) - assert := assert.New(t) - maintenance, logs := newFailingAttachmentMaintenance(t) - warningErr := errors.New("warning stream closed") - - err := runAfterSuccessfulAttachmentIngest( - context.Background(), - maintenance, - func(context.Context) error { return nil }, - func(string) error { return warningErr }, - ) - - require.NoError(err, "warning failure must preserve successful ingest") - assert.Contains(logs.String(), "failed to emit automatic attachment maintenance warning") - assert.Contains(logs.String(), warningErr.Error()) -} - func (f *attachmentMaintenanceFixture) ingestLoose(content []byte) string { f.t.Helper() f.sequence++ @@ -686,14 +653,17 @@ func TestPendingPackCheckpointsVerificationAndStillPacksNewBlobs(t *testing.T) { require.NoError(err) fresh := f.addLoose([]byte("new attachment while verification is pending")) f.maintenance.markPackPending() - require.ErrorIs(f.maintenance.runPendingPack(t.Context()), scheduler.ErrReschedule) + require.NoError(f.maintenance.runPendingPack(t.Context()), + "one window of verification does not chain the whole cycle") require.NotNil(f.packedEntry(fresh), "new blobs must not wait for the whole verification cycle") // A reconstructed daemon resumes the durable verification cursor. resumed, err := newAttachmentMaintenance(f.store, f.dir, nil, true) require.NoError(err) defer func() { require.NoError(resumed.close()) }() - resumed.markPackPending() - require.NoError(resumed.runPendingPack(t.Context())) + ctx := jobctx.WithProgress(t.Context()) + verifyMore, err := resumed.runScheduledPack(ctx) + require.NoError(err) + assert.False(t, verifyMore, "the second window finishes the cycle the first pass started") stats, err := resumed.unpack(t.Context()) require.NoError(err) assert.Equal(t, existing+1, stats.BlobsRestored, "manual unpack must see the full catalog") @@ -702,7 +672,9 @@ func TestPendingPackCheckpointsVerificationAndStillPacksNewBlobs(t *testing.T) { func TestCompletedPackVerificationRecordsNoProgress(t *testing.T) { f := newAttachmentMaintenanceFixture(t) ctx := jobctx.WithProgress(t.Context()) - require.NoError(t, f.maintenance.runScheduledPack(ctx)) + verifyMore, err := f.maintenance.runScheduledPack(ctx) + require.NoError(t, err) + assert.False(t, verifyMore) assert.False(t, jobctx.HasProgress(ctx), "an empty completed scan provides no resume point for a cancelled repack") } @@ -749,7 +721,248 @@ func TestRemovingRedundantOrphanPackCountsAsProgress(t *testing.T) { require.NoError(os.MkdirAll(filepath.Dir(orphan), 0o700)) require.NoError(os.WriteFile(orphan, data, 0o600)) ctx := jobctx.WithProgress(t.Context()) - require.NoError(f.maintenance.runAutomaticPack(ctx, nil)) + require.NoError(f.maintenance.runAutomaticPack(ctx)) assert.NoFileExists(t, orphan) assert.True(t, jobctx.HasProgress(ctx), "a removed pack is committed progress a timed-out pass can resume after") } + +// holdPackPass stands in for a pass that cannot finish quickly: an +// attachment mutation in progress keeps Pack waiting for its exclusive lease, +// exactly where a pass waits behind a running ingest. +func (f *attachmentMaintenanceFixture) holdPackPass() func() { + f.t.Helper() + lease, err := f.maintenance.coordinator.AcquireMutation(f.t.Context()) + require.NoError(f.t, err) + return func() { require.NoError(f.t, lease.Release()) } +} + +func TestBackgroundPackKeepsIdleDaemonAliveUntilItFinishes(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + hash := f.addLoose([]byte("blob packed while the daemon would otherwise idle out")) + const idleTimeout = 20 * time.Second + idleShutdown := make(chan struct{}) + idle := api.NewIdleTracker(idleTimeout, func() { close(idleShutdown) }) + sched, media := newServeSchedulers(nil, f.maintenance.logger, idle, api.NewSerialOperationGate()) + defer func() { <-serveSchedulers{sched, media}.Stop().Done() }() + require.NoError(registerAttachmentPackJob(sched, f.maintenance)) + go idle.Run(t.Context()) + release := f.holdPackPass() + + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, nil)) + // Longer than the idle timeout, shorter than the job's runtime limit. + synctest.Sleep(2 * idleTimeout) + select { + case <-idleShutdown: + require.FailNow("the daemon idled out while its pack job was running") + default: + } + require.Less(2*idleTimeout, automaticAttachmentMaxRuntime) + assert.True(attachmentPackJobStatus(t, sched).Running) + + release() + synctest.Wait() + assert.NotNil(f.packedEntry(hash), "the pass finishes once it can take the maintenance lease") + select { + case <-idleShutdown: + require.FailNow("idle timeout must count from the end of the pack job") + default: + } + synctest.Sleep(idleTimeout + time.Second) + select { + case <-idleShutdown: + default: + assert.Fail("an idle daemon must still shut down after packing") + } + }) +} + +func TestBackgroundPackStopsAtRuntimeLimitAndNextIngestResumesIt(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + hash := f.addLoose([]byte("blob whose first pass runs out of time")) + sched, _ := newBackgroundPackHarness(t, f) + release := f.holdPackPass() + + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, nil)) + synctest.Sleep(automaticAttachmentMaxRuntime + time.Second) + synctest.Wait() + + status := attachmentPackJobStatus(t, sched) + assert.False(status.Running, "the runtime limit ends the pass and releases the gate") + assert.False(status.Pending, "a pass without committed progress waits for the next trigger") + assert.Contains(status.LastError, jobctx.ErrRunBudgetExceeded.Error()) + assert.Nil(f.packedEntry(hash)) + assert.True(f.maintenance.packPending.Load(), "the unfinished work stays pending") + + release() + // The next manual ingest reports the failed pass and restarts the job, + // which picks up the pending work. + var notices []string + collect := func(message string) error { + notices = append(notices, message) + return nil + } + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, collect)) + require.Len(notices, 1, "one notice about the failed pass") + assert.Contains(notices[0], "last background attachment packing pass failed") + assert.Contains(notices[0], jobctx.ErrRunBudgetExceeded.Error()) + assert.Contains(notices[0], "msgvault pack-attachments") + assert.Equal(1, strings.Count(notices[0], "\n"), "the notice is one line") + synctest.Wait() + assert.NotNil(f.packedEntry(hash)) + assert.False(f.maintenance.packPending.Load()) + assert.Empty(attachmentPackJobStatus(t, sched).LastError) + + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, collect)) + assert.Len(notices, 1, "a clean pass clears the notice") + synctest.Wait() + }) +} + +func TestPackFailureNoticeCannotFailTheIngest(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + f.addLoose([]byte("blob whose pass fails before a disconnected client returns")) + _, _ = newBackgroundPackHarness(t, f) + release := f.holdPackPass() + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, nil)) + synctest.Sleep(automaticAttachmentMaxRuntime + time.Second) + synctest.Wait() + release() + + err := runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, + func(string) error { return errors.New("client disconnected") }) + + require.NoError(err, "a notice that cannot be delivered never fails the ingest") + synctest.Wait() // the requested pass also writes to the log + assert.Contains(f.logs.String(), "failed to emit attachment packing notice") + assert.Contains(f.logs.String(), "client disconnected") + }) +} + +// TestQueuedPackJobCountsAsDaemonActivity covers the window before the job +// holds the operation gate: another holder keeps it queued past the idle +// timeout, and the daemon must not stop with packing still waiting. +func TestQueuedPackJobCountsAsDaemonActivity(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + hash := f.addLoose([]byte("blob queued behind another gate holder")) + const idleTimeout = 20 * time.Second + idleShutdown := make(chan struct{}) + idle := api.NewIdleTracker(idleTimeout, func() { close(idleShutdown) }) + gate := api.NewSerialOperationGate() + sched, media := newServeSchedulers(nil, f.maintenance.logger, idle, gate) + defer func() { <-serveSchedulers{sched, media}.Stop().Done() }() + require.NoError(registerAttachmentPackJob(sched, f.maintenance)) + go idle.Run(t.Context()) + releaseGate, ok := gate.BeginLabeledWorkContext(t.Context(), "other archive work") + require.True(ok) + + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, nil)) + synctest.Sleep(2 * idleTimeout) + select { + case <-idleShutdown: + require.FailNow("the daemon idled out while its pack job waited for the gate") + default: + } + status := attachmentPackJobStatus(t, sched) + assert.True(status.Queued, "the job is still waiting for the gate") + assert.Nil(f.packedEntry(hash)) + + releaseGate() + synctest.Wait() + assert.NotNil(f.packedEntry(hash)) + synctest.Sleep(idleTimeout + time.Second) + select { + case <-idleShutdown: + default: + assert.Fail("an idle daemon must still shut down after packing") + } + }) +} + +// TestDailyMaintenanceChainsTheWholeVerificationCycle runs the daily job the +// way the scheduler does, one pass per follow-up, and checks that it verifies +// every window before it repacks. +func TestDailyMaintenanceChainsTheWholeVerificationCycle(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + for i := range 140 { // two verification windows: 128 + 12 + f.addLoose([]byte(fmt.Sprintf("packed before the daily job %d", i))) + } + _, err := f.maintenance.pack(t.Context(), 0) + require.NoError(err) + + followUps := 0 + for { + err := f.maintenance.daily(t.Context()) + if !errors.Is(err, scheduler.ErrReschedule) { + require.NoError(err) + break + } + followUps++ + require.Less(followUps, 10, "the daily chain must end") + } + + assert.Equal(1, followUps, "the second window needs one follow-up") + var cursor string + require.NoError(f.store.DB().QueryRow(f.store.Rebind( + `SELECT value FROM archive_metadata WHERE key = ?`), "attachment_pack_verification_cursor").Scan(&cursor)) + assert.Empty(cursor, "a finished cycle resets the verification cursor") + assert.Equal(2, strings.Count(f.logs.String(), "automatic attachment maintenance complete")) + assert.Equal(1, strings.Count(f.logs.String(), "automatic attachment repack complete"), + "repack runs once, after the cycle") +} + +func TestBackgroundPackCancelsOnShutdownAndRestartResumesIt(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + hash := f.addLoose([]byte("blob whose pass is interrupted by shutdown")) + gate := api.NewSerialOperationGate() + sched, media := newServeSchedulers(nil, f.maintenance.logger, nil, gate) + require.NoError(registerAttachmentPackJob(sched, f.maintenance)) + release := f.holdPackPass() + + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), f.maintenance, + func(context.Context) error { return nil }, nil)) + synctest.Wait() + require.True(attachmentPackJobStatus(t, sched).Running) + require.NoError(shutdownServeRuntime(t.Context(), io.Discard, nil, + serveSchedulers{sched, media}, gate)) + assert.Nil(f.packedEntry(hash), "a cancelled pass commits nothing") + assert.Contains(f.logs.String(), "automatic attachment maintenance canceled") + release() + + // A restarted daemon has no in-memory request; its job rechecks the + // catalog on the first pass after startup. + restarted, err := newAttachmentMaintenance(f.store, f.dir, f.maintenance.logger, true) + require.NoError(err) + defer func() { require.NoError(restarted.close()) }() + restartedSched := scheduler.New(nil).WithLogger(f.maintenance.logger) + defer func() { <-restartedSched.Stop().Done() }() + require.NoError(registerAttachmentPackJob(restartedSched, restarted)) + require.NoError(runAfterSuccessfulAttachmentIngest(t.Context(), restarted, + func(context.Context) error { return nil }, nil)) + synctest.Wait() + assert.NotNil(f.packedEntry(hash)) + }) +} diff --git a/cmd/msgvault/cmd/serve.go b/cmd/msgvault/cmd/serve.go index e8c814cef8..fd0c859518 100644 --- a/cmd/msgvault/cmd/serve.go +++ b/cmd/msgvault/cmd/serve.go @@ -2085,15 +2085,12 @@ func (a *storeAPIAdapter) runCLISyncWithRunner( } return emit(api.CLISyncEvent{Type: stream, Data: data}) } - emitWarning := func(message string) error { - if emit == nil { - return nil - } - return emit(api.CLISyncEvent{Type: "stderr", Data: message}) + emitNotice := func(message string) error { + return emitSubprocess(cliStreamStderr, message) } return runAfterSuccessfulAttachmentIngest(ctx, a.attachmentMaintenance, func(ctx context.Context) error { return run(ctx, cliSyncSubprocessArgs(req), emitSubprocess) - }, emitWarning) + }, emitNotice) } // emitFolderArgs appends a --folder/--skip-folder flag for each @@ -2230,13 +2227,10 @@ func (a *storeAPIAdapter) runCLIRepairMessageWithRunner( if req.Audit { return runRepair(ctx) } - emitWarning := func(message string) error { - if emit == nil { - return nil - } - return emit(api.CLIRepairMessageEvent{Type: "stderr", Data: message}) + emitNotice := func(message string) error { + return emitSubprocess(cliStreamStderr, message) } - return runAfterSuccessfulAttachmentIngest(ctx, a.attachmentMaintenance, runRepair, emitWarning) + return runAfterSuccessfulAttachmentIngest(ctx, a.attachmentMaintenance, runRepair, emitNotice) } func cliRepairMessageSubprocessArgs(req api.CLIRepairMessageRequest) []string { @@ -2349,18 +2343,10 @@ func (a *storeAPIAdapter) runCLICommandWithRunner( ctx, a.attachmentMaintenance, runSubprocess, emitWarning, ) } - emitWarning := func(message string) error { - if emit == nil { - return nil - } - return emit(api.CLIRunEvent{Type: "stderr", Data: message}) + emitNotice := func(message string) error { + return emitSubprocess(cliStreamStderr, message) } - return runAfterSuccessfulAttachmentIngest( - ctx, - a.attachmentMaintenance, - runSubprocess, - emitWarning, - ) + return runAfterSuccessfulAttachmentIngest(ctx, a.attachmentMaintenance, runSubprocess, emitNotice) } func attachmentRemovalCommand(args []string) bool { diff --git a/cmd/msgvault/cmd/serve_test.go b/cmd/msgvault/cmd/serve_test.go index 17dc0fca8a..1957c6b902 100644 --- a/cmd/msgvault/cmd/serve_test.go +++ b/cmd/msgvault/cmd/serve_test.go @@ -20,6 +20,7 @@ import ( "strings" "sync" "testing" + "testing/synctest" "time" "github.com/spf13/cobra" @@ -2037,52 +2038,92 @@ func TestStoreAPIAdapterServesSourceStatus(t *testing.T) { assert.Equal(store.SyncStatusCompleted, got.LastSuccessfulSync.Status, "LastSuccessfulSync.Status") } -func TestStoreAPIAdapterRunCLISyncPacksOnlyAfterSubprocessSuccess(t *testing.T) { +// newBackgroundPackHarness wires the attachment-pack job the way the daemon +// does: on the daemon scheduler, behind the operation gate. The startup +// catalog recheck is cleared so a test observes only what a request asks for; +// TestRegisterAttachmentPackJobFindsBacklogAfterRestart covers that recheck. +func newBackgroundPackHarness(t *testing.T, f *attachmentMaintenanceFixture) (*scheduler.Scheduler, *api.SerialOperationGate) { + t.Helper() + gate := api.NewSerialOperationGate() + sched, media := newServeSchedulers(nil, f.maintenance.logger, nil, gate) + t.Cleanup(func() { <-serveSchedulers{sched, media}.Stop().Done() }) + require.NoError(t, registerAttachmentPackJob(sched, f.maintenance)) + f.maintenance.packPending.Store(false) + return sched, gate +} + +func attachmentPackJobStatus(t *testing.T, sched *scheduler.Scheduler) scheduler.JobStatus { + t.Helper() + for _, status := range sched.JobStatus() { + if status.Name == attachmentPackJob { + return status + } + } + require.FailNow(t, "attachment-pack job is not registered") + return scheduler.JobStatus{} +} + +// TestStoreAPIAdapterRunCLISyncReturnsBeforeBackgroundPack proves a manual +// sync's request finishes without packing: the pack job only queues for the +// operation gate the request still holds, and packs once it is released. +func TestStoreAPIAdapterRunCLISyncReturnsBeforeBackgroundPack(t *testing.T) { tests := []struct { name string predecessorErr error wantPacked bool - wantAttempts int }{ - {name: "success", wantPacked: true, wantAttempts: 1}, + {name: "success", wantPacked: true}, {name: "failure", predecessorErr: errors.New("sync subprocess failed")}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - require := require.New(t) - assert := assert.New(t) - f := newAttachmentMaintenanceFixture(t) - hash := f.addLoose([]byte("CLI sync attachment payload")) - adapter := &storeAPIAdapter{store: f.store, attachmentMaintenance: f.maintenance} - var events []api.CLISyncEvent - runnerCalls := 0 - - err := adapter.runCLISyncWithRunner( - context.Background(), - api.CLISyncRequest{Email: "alice@example.com"}, - func(event api.CLISyncEvent) error { - events = append(events, event) - return nil - }, - func(_ context.Context, args []string, _ func(string, string) error) error { - runnerCalls++ - assert.Equal([]string{"sync", "alice@example.com"}, args) - assert.Nil(f.packedEntry(hash), "packing must follow subprocess success") - return tt.predecessorErr - }, - ) - - if tt.predecessorErr != nil { - require.ErrorIs(err, tt.predecessorErr) - } else { - require.NoError(err) - } - assert.Equal(1, runnerCalls) - assert.Equal(tt.wantPacked, f.packedEntry(hash) != nil) - assert.Equal(tt.wantAttempts, - strings.Count(f.logs.String(), "automatic attachment maintenance complete")) - assert.Empty(events, "successful automatic maintenance writes no normal CLI output") + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + hash := f.addLoose([]byte("CLI sync attachment payload")) + sched, gate := newBackgroundPackHarness(t, f) + adapter := &storeAPIAdapter{store: f.store, attachmentMaintenance: f.maintenance} + var events []api.CLISyncEvent + runnerCalls := 0 + + // The API middleware holds the gate for the whole request. + releaseRequest, ok := gate.BeginRequestWorkContext(t.Context(), "msgvault sync") + require.True(ok) + err := adapter.runCLISyncWithRunner( + t.Context(), + api.CLISyncRequest{Email: "alice@example.com"}, + func(event api.CLISyncEvent) error { + events = append(events, event) + return nil + }, + func(_ context.Context, args []string, _ func(string, string) error) error { + runnerCalls++ + assert.Equal([]string{"sync", "alice@example.com"}, args) + return tt.predecessorErr + }, + ) + if tt.predecessorErr != nil { + require.ErrorIs(err, tt.predecessorErr) + } else { + require.NoError(err) + } + assert.Equal(1, runnerCalls) + assert.Empty(events, "packing writes no CLI output") + synctest.Wait() + assert.Nil(f.packedEntry(hash), "the request returns before any packing") + assert.Equal(tt.wantPacked, attachmentPackJobStatus(t, sched).Queued, + "only a successful sync queues the pack job behind its request") + + releaseRequest() + synctest.Wait() + assert.Equal(tt.wantPacked, f.packedEntry(hash) != nil) + status := attachmentPackJobStatus(t, sched) + assert.False(status.Running) + assert.Empty(status.LastError) + assert.Equal(tt.wantPacked, !status.LastRun.IsZero()) + }) }) } } @@ -2287,19 +2328,88 @@ func TestStoreAPIAdapterFinalizesSyncOperationAfterRunnerReturns(t *testing.T) { assert.Equal("done", op.Status) } +// TestStoreAPIAdapterIngestsReportPreviousPackFailure proves each ingest +// request tells its CLI, on stderr, that the last background pack pass failed. +func TestStoreAPIAdapterIngestsReportPreviousPackFailure(t *testing.T) { + ingests := map[string]func(*storeAPIAdapter, context.Context) ([]string, error){ + "sync": func(a *storeAPIAdapter, ctx context.Context) ([]string, error) { + var stderr []string + err := a.runCLISyncWithRunner(ctx, api.CLISyncRequest{Email: "alice@example.com"}, + func(event api.CLISyncEvent) error { + if event.Type == cliStreamStderr { + stderr = append(stderr, event.Data) + } + return nil + }, + func(context.Context, []string, func(string, string) error) error { return nil }) + return stderr, err + }, + "import": func(a *storeAPIAdapter, ctx context.Context) ([]string, error) { + var stderr []string + err := a.runCLICommandWithRunner(ctx, api.CLIRunRequest{Args: []string{importMboxCommand, "archive.mbox"}}, + func(event api.CLIRunEvent) error { + if event.Type == cliStreamStderr { + stderr = append(stderr, event.Data) + } + return nil + }, + func(context.Context, []string, map[string]string, string, func(string, string) error) error { + return nil + }) + return stderr, err + }, + "repair": func(a *storeAPIAdapter, ctx context.Context) ([]string, error) { + var stderr []string + err := a.runCLIRepairMessageWithRunner(ctx, api.CLIRepairMessageRequest{Reference: "gmail-42"}, + func(event api.CLIRepairMessageEvent) error { + if event.Type == cliStreamStderr { + stderr = append(stderr, event.Data) + } + return nil + }, + func(context.Context, []string, func(string, string) error) error { return nil }) + return stderr, err + }, + } + for name, ingest := range ingests { + t.Run(name, func(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + f.addLoose([]byte("blob whose first background pass fails")) + _, _ = newBackgroundPackHarness(t, f) + adapter := &storeAPIAdapter{store: f.store, attachmentMaintenance: f.maintenance} + release := f.holdPackPass() + _, err := ingest(adapter, t.Context()) + require.NoError(err) + synctest.Sleep(automaticAttachmentMaxRuntime + time.Second) + synctest.Wait() + release() + + stderr, err := ingest(adapter, t.Context()) + + require.NoError(err) + require.Len(stderr, 1) + assert.Contains(stderr[0], "last background attachment packing pass failed") + assert.Contains(stderr[0], "msgvault pack-attachments") + synctest.Wait() + }) + }) + } +} + func TestStoreAPIAdapterRunCLICommandPacksOnlyAllowlistedSuccess(t *testing.T) { tests := []struct { name string args []string predecessorErr error wantPacked bool - wantAttempts int }{ { - name: "allowlisted success", - args: []string{importMboxCommand, "archive.mbox"}, - wantPacked: true, - wantAttempts: 1, + name: "allowlisted success", + args: []string{importMboxCommand, "archive.mbox"}, + wantPacked: true, }, { name: "unrelated success", @@ -2314,47 +2424,51 @@ func TestStoreAPIAdapterRunCLICommandPacksOnlyAllowlistedSuccess(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - require := require.New(t) - assert := assert.New(t) - f := newAttachmentMaintenanceFixture(t) - hash := f.addLoose([]byte("generic CLI attachment payload")) - adapter := &storeAPIAdapter{store: f.store, attachmentMaintenance: f.maintenance} - var events []api.CLIRunEvent - runnerCalls := 0 - - err := adapter.runCLICommandWithRunner( - context.Background(), - api.CLIRunRequest{Args: tt.args, Env: map[string]string{"TEST": "value"}, Cwd: "/tmp"}, - func(event api.CLIRunEvent) error { - events = append(events, event) - return nil - }, - func( - _ context.Context, - args []string, - env map[string]string, - cwd string, - _ func(string, string) error, - ) error { - runnerCalls++ - assert.Equal(tt.args, args) - assert.Equal(map[string]string{"TEST": "value"}, env) - assert.Equal("/tmp", cwd) - assert.Nil(f.packedEntry(hash), "packing must follow subprocess success") - return tt.predecessorErr - }, - ) + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + f := newAttachmentMaintenanceFixture(t) + hash := f.addLoose([]byte("generic CLI attachment payload")) + sched, _ := newBackgroundPackHarness(t, f) + adapter := &storeAPIAdapter{store: f.store, attachmentMaintenance: f.maintenance} + var events []api.CLIRunEvent + runnerCalls := 0 + + err := adapter.runCLICommandWithRunner( + t.Context(), + api.CLIRunRequest{Args: tt.args, Env: map[string]string{"TEST": "value"}, Cwd: "/tmp"}, + func(event api.CLIRunEvent) error { + events = append(events, event) + return nil + }, + func( + _ context.Context, + args []string, + env map[string]string, + cwd string, + _ func(string, string) error, + ) error { + runnerCalls++ + assert.Equal(tt.args, args) + assert.Equal(map[string]string{"TEST": "value"}, env) + assert.Equal("/tmp", cwd) + assert.Nil(f.packedEntry(hash), "packing must follow subprocess success") + return tt.predecessorErr + }, + ) - if tt.predecessorErr != nil { - require.ErrorIs(err, tt.predecessorErr) - } else { - require.NoError(err) - } - assert.Equal(1, runnerCalls) - assert.Equal(tt.wantPacked, f.packedEntry(hash) != nil) - assert.Equal(tt.wantAttempts, - strings.Count(f.logs.String(), "automatic attachment maintenance complete")) - assert.Empty(events, "successful automatic maintenance writes no normal CLI output") + if tt.predecessorErr != nil { + require.ErrorIs(err, tt.predecessorErr) + } else { + require.NoError(err) + } + assert.Equal(1, runnerCalls) + synctest.Wait() + assert.Equal(tt.wantPacked, f.packedEntry(hash) != nil) + assert.Equal(tt.wantPacked, !attachmentPackJobStatus(t, sched).LastRun.IsZero(), + "only successful attachment-producing commands start the pack job") + assert.Empty(events, "background packing writes no CLI output") + }) }) } } @@ -2657,7 +2771,7 @@ func TestStoreAPIAdapterExplicitRepackCancellationFailsFast(t *testing.T) { assert.True(has, "fail-fast cancellation leaves physical inventory untouched") } -func TestStoreAPIAdapterMaintenanceWarningStreamsWithoutChangingSuccess(t *testing.T) { +func TestStoreAPIAdapterSyncDoesNotPackInsideTheRequest(t *testing.T) { require := require.New(t) assert := assert.New(t) maintenance, logs := newFailingAttachmentMaintenance(t) @@ -2674,33 +2788,34 @@ func TestStoreAPIAdapterMaintenanceWarningStreamsWithoutChangingSuccess(t *testi func(context.Context, []string, func(string, string) error) error { return nil }, ) - require.NoError(err, "automatic maintenance failure must preserve sync success") - require.Len(events, 1, "one concise warning event") - assert.Equal("stderr", events[0].Type) - assert.Contains(events[0].Data, "pack-attachments") - assert.Contains(events[0].Data, "retry") - assert.Contains(logs.String(), "automatic attachment maintenance failed") + require.NoError(err, "a maintenance fault cannot fail the sync request") + assert.Empty(events, "the request streams only the sync's own output") + assert.True(maintenance.packPending.Load(), "the sync leaves its pack request pending") + assert.NotContains(logs.String(), "automatic attachment maintenance", "no pack pass ran inside the request") } - -func TestStoreAPIAdapterMaintenanceWarningStreamFailurePreservesSuccess(t *testing.T) { +func TestStoreAPIAdapterImportDoesNotPackInsideTheRequest(t *testing.T) { require := require.New(t) assert := assert.New(t) maintenance, logs := newFailingAttachmentMaintenance(t) adapter := &storeAPIAdapter{store: maintenance.store, attachmentMaintenance: maintenance} - warningErr := errors.New("client disconnected") + emitted := 0 err := adapter.runCLICommandWithRunner( context.Background(), api.CLIRunRequest{Args: []string{importMboxCommand, "archive.mbox"}}, - func(api.CLIRunEvent) error { return warningErr }, + func(api.CLIRunEvent) error { + emitted++ + return errors.New("client disconnected") + }, func(context.Context, []string, map[string]string, string, func(string, string) error) error { return nil }, ) - require.NoError(err, "warning stream failure must preserve command success") - assert.Contains(logs.String(), "failed to emit automatic attachment maintenance warning") - assert.Contains(logs.String(), warningErr.Error()) + require.NoError(err, "a maintenance fault cannot fail the import request") + assert.Zero(emitted, "the request streams only the import's own output") + assert.True(maintenance.packPending.Load(), "the import leaves its pack request pending") + assert.NotContains(logs.String(), "automatic attachment maintenance", "no pack pass ran inside the request") } func TestStoreAPIAdapterServesCLIInitDB(t *testing.T) { diff --git a/docs/changelog.md b/docs/changelog.md index 5ab743dc8d..b5fe514844 100644 --- a/docs/changelog.md +++ b/docs/changelog.md @@ -1,5 +1,5 @@ --- -last_edited: "2026-10-05" +last_edited: "2026-10-14" title: Changelog description: Release history for msgvault --- @@ -8,6 +8,14 @@ All notable changes to msgvault, grouped by release. ## Unreleased +- A `sync` or import sent to the daemon returns when its own work finishes. + Attachment packing now runs afterwards as the daemon's bounded + `attachment-pack` job instead of inside the request. A daemon started on + demand stays up until that job finishes, and the next such command warns + when the previous background pass failed. Each pass verifies one bounded + window of existing packs instead of every packed blob, and finding new loose + blobs no longer reads every attachment row. + - `add-o365 --graph --as ` syncs a shared or delegated Microsoft 365 mailbox through Microsoft Graph, signed in as you. It needs the `Mail.Read.Shared` permission. See diff --git a/docs/cli-reference.md b/docs/cli-reference.md index 76ba6a5d6e..831b54770d 100644 --- a/docs/cli-reference.md +++ b/docs/cli-reference.md @@ -1,5 +1,5 @@ --- -last_edited: "2026-10-05" +last_edited: "2026-10-14" title: CLI Reference description: Complete command reference for all msgvault commands. --- @@ -1783,22 +1783,38 @@ msgvault pack-attachments The daemon serializes packing against sync and backup operations. Reads remain available from loose, packed, or mixed storage, and the command is safe to -rerun as new loose content arrives. Bounded packing also runs after successful -attachment-producing commands sent to the daemon. Scheduled syncs never pack -inline: when one writes new loose blobs, the daemon's `attachment-pack` job -(every 6 hours) packs them, and the daily `attachment-maintenance` job packs -and repacks. Each automatic pack pass has a 256 MiB soft raw-byte budget and -finishes its current blob before stopping for that byte limit. Scheduled packing -and daily attachment maintenance also stop after one minute, which lets queued -scheduled work run. Each scheduled pack pass verifies at most 128 -existing packed blobs or 32 MiB of their raw content, allowing one oversized -blob. Its durable hash cursor resumes verification after a restart, while new -loose blobs can be packed during each pass. Manual unpacking reads the full -catalog. Cancellation preserves committed packs. A pass with committed -progress resumes behind waiting work; runtime expiry without a checkpoint -records an error and waits for the next trigger. The first pack tick after a -restart also checks for blobs left by the previous daemon. -This command processes the complete eligible backlog immediately. +rerun as new loose content arrives. This command processes the complete +eligible backlog immediately. + +The daemon also packs automatically: + +- After a successful attachment-producing command sent to the daemon, such as + `sync` or an import, the command returns as soon as its own work finishes. + The daemon then starts its `attachment-pack` job in the background. A daemon + started on demand stays running while that job waits and runs, and still + stops after its idle timeout once the job finishes. If the job's previous + pass failed, the command prints a one-line warning on stderr; run + `msgvault pack-attachments` to retry. +- The `attachment-pack` job also runs every 6 hours, which packs loose blobs + written by scheduled syncs. Scheduled syncs never pack inline. +- The daily `attachment-maintenance` job packs, finishes a verification + cycle, and repacks. + +Each automatic pack pass has a 256 MiB soft raw-byte budget and finishes its +current blob before stopping for that byte limit. Passes stop after one minute, +which lets queued work run, and yield to waiting requests. Each pass also +verifies the next window of at most 128 existing packed blobs or 32 MiB of +their raw content, allowing one oversized blob, instead of every packed blob. +A pass still lists every attachment hash and checks every pack file, so it +takes longer on a larger archive even when little is new. A durable hash +cursor resumes verification after a restart. The `attachment-pack` job +verifies one window per pass and queues follow-ups only while loose blobs +remain; the daily job continues until the whole cycle is verified. Manual unpacking reads the full +catalog. Cancellation, including daemon shutdown, preserves committed packs. A +pass with committed progress resumes behind waiting work; runtime expiry +without a checkpoint records an error and waits for the next trigger, such as +the next sync. The first pack pass after a restart also checks for blobs left +by the previous daemon. With `[data].loose_attachments = true`, automatic packing is disabled and this command refuses to run. diff --git a/internal/scheduler/scheduler.go b/internal/scheduler/scheduler.go index ef3d096ca6..f5cb95561b 100644 --- a/internal/scheduler/scheduler.go +++ b/internal/scheduler/scheduler.go @@ -830,6 +830,26 @@ func (s *Scheduler) StartJob(name string) error { return nil } +// RequestJob asks for one run of the named generic job without waiting for +// it. Like StartJob, it returns once the run is reserved, so a caller that +// holds the daemon's operation gate releases it before the job acquires it. +// Like a cron tick, a request that finds the job executing queues one +// follow-up run instead of being dropped, and a request that finds a run +// still waiting to start is absorbed by that run. +func (s *Scheduler) RequestJob(name string) error { + run, ok, err := s.reserveGenericJob(name, true) + if err != nil { + return err + } + if !ok { + return nil + } + go func() { + _ = s.runJob(name, run) + }() + return nil +} + // onJobTick handles one cron firing for a generic job, coalescing a tick // that arrives while the job is active like onAccountTick does. func (s *Scheduler) onJobTick(name string) { diff --git a/internal/scheduler/scheduler_test.go b/internal/scheduler/scheduler_test.go index 5cf4a9b0d5..f03b46895f 100644 --- a/internal/scheduler/scheduler_test.go +++ b/internal/scheduler/scheduler_test.go @@ -267,6 +267,55 @@ func TestStartJobIsAsync(t *testing.T) { }) } +// TestRequestJobCoalescesLikeATick proves RequestJob returns before the job +// holds the work gate, that a request made while a run waits for the gate is +// absorbed by that run, and that a request made while a run executes queues +// exactly one follow-up instead of being dropped. +func TestRequestJobCoalescesLikeATick(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + require := require.New(t) + assert := assert.New(t) + var runs atomic.Int32 + release := make(chan struct{}) + tracker := newSerialWorkTracker() + s := New(func(context.Context, string) error { return nil }).WithWorkTracker(tracker) + defer func() { <-s.Stop().Done() }() + require.NoError(s.AddJob(Job{Name: "job", Schedule: "0 0 1 1 *", Run: func(context.Context) error { + if runs.Add(1) == 1 { + <-release + } + return nil + }})) + + // The caller holds the gate, as an HTTP handler does. + holding, ok := tracker.BeginWork() + require.True(ok) + require.NoError(s.RequestJob("job"), "request while the caller holds the gate") + synctest.Wait() + assert.True(s.JobStatus()[0].Queued, "the run waits for the caller's gate") + require.NoError(s.RequestJob("job"), "request while a run waits to start") + assert.False(s.JobStatus()[0].Pending, "a waiting run absorbs the request") + assert.Equal(int32(0), runs.Load()) + + holding() + synctest.Wait() + require.Equal(int32(1), runs.Load(), "the run starts once the caller releases the gate") + require.NoError(s.RequestJob("job"), "request while the run executes") + require.NoError(s.RequestJob("job"), "a second request coalesces into the same follow-up") + assert.True(s.JobStatus()[0].Pending, "an executing run queues one follow-up") + + close(release) + synctest.Wait() + assert.Equal(int32(2), runs.Load(), "exactly one follow-up runs") + assert.False(s.JobStatus()[0].Running) + + require.Error(s.RequestJob("missing"), "unknown jobs are rejected") + <-s.Stop().Done() + require.Error(s.RequestJob("job"), "a stopped scheduler starts nothing") + assert.Equal(int32(2), runs.Load()) + }) +} + func TestStartStop(t *testing.T) { s := New(func(ctx context.Context, email string) error { return nil diff --git a/internal/store/pack_liveness_index_test.go b/internal/store/pack_liveness_index_test.go index 047dd9da8f..9392504732 100644 --- a/internal/store/pack_liveness_index_test.go +++ b/internal/store/pack_liveness_index_test.go @@ -47,3 +47,33 @@ func TestAttachmentPackLivenessQueriesUseExpressionIndexes(t *testing.T) { }) } } + +func TestUnpackedBlobQueriesReadOnlyCandidateRows(t *testing.T) { + require := require.New(t) + dir := t.TempDir() + st, err := OpenForTest(filepath.Join(dir, "unpacked.db")) + require.NoError(err) + defer func() { require.NoError(st.Close()) }() + require.NoError(st.InitSchema()) + + tests := map[string]struct { + sql string + index string + key string + }{ + "content": {sql: listUnpackedContentBlobsSQL, index: "idx_attachments_hash", key: "content_hash"}, + "thumbnail": {sql: listUnpackedThumbnailBlobsSQL, index: "idx_attachments_thumbnail_hash", key: "thumbnail_hash"}, + } + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + assert := assert.New(t) + plan := explainPlan(t, st, tc.sql) + t.Logf("query plan:\n%s", plan) + assert.Contains(plan, "candidate USING COVERING INDEX "+tc.index, + "candidates must come from the hash index without reading attachment rows:\n%s", plan) + assert.Contains(plan, "SEARCH attachments USING INDEX "+tc.index+" ("+tc.key+"=?)", + "attachment rows must be read only for candidate hashes:\n%s", plan) + assert.NotContains(plan, "SCAN attachments", "no attachment table scan:\n%s", plan) + }) + } +} diff --git a/internal/store/pack_unpacked_equivalence_test.go b/internal/store/pack_unpacked_equivalence_test.go new file mode 100644 index 0000000000..968e999d47 --- /dev/null +++ b/internal/store/pack_unpacked_equivalence_test.go @@ -0,0 +1,203 @@ +package store + +// The unpacked-blob queries read attachment rows only for candidate hashes. +// This test holds them to the plain row-by-row definition below, which tests +// every attachment row against the pack index, on seeded random archives with +// mixed-case, NULL, empty, BLOB, and integer hash values. + +import ( + "fmt" + "math/rand/v2" + "path/filepath" + "strings" + "testing" + + "github.com/stretchr/testify/require" +) + +const rowByRowUnpackedContentSQL = ` + SELECT content_hash, storage_path, COALESCE(MAX(size), -1) + FROM attachments + WHERE content_hash IS NOT NULL AND content_hash != '' + AND storage_path IS NOT NULL AND storage_path != '' + AND LOWER(storage_path) NOT LIKE 'http://%' + AND LOWER(storage_path) NOT LIKE 'https://%' + AND NOT EXISTS (SELECT 1 FROM attachment_pack_index p + WHERE p.blob_hash = LOWER(attachments.content_hash)) + GROUP BY content_hash, storage_path + ORDER BY MIN(id), storage_path` + +const rowByRowUnpackedThumbnailSQL = ` + SELECT thumbnail_hash, thumbnail_path + FROM attachments + WHERE thumbnail_hash IS NOT NULL AND thumbnail_hash != '' + AND thumbnail_path IS NOT NULL AND thumbnail_path != '' + AND LOWER(thumbnail_path) NOT LIKE 'http://%' + AND LOWER(thumbnail_path) NOT LIKE 'https://%' + AND NOT EXISTS (SELECT 1 FROM attachment_pack_index p + WHERE p.blob_hash = LOWER(attachments.thumbnail_hash)) + GROUP BY thumbnail_hash, thumbnail_path + ORDER BY MIN(id), thumbnail_path` + +func dumpUnpackedQuery(t *testing.T, st *Store, query string) []string { + t.Helper() + rows, err := st.db.QueryContext(t.Context(), query) + require.NoError(t, err) + defer func() { _ = rows.Close() }() + cols, err := rows.Columns() + require.NoError(t, err) + var out []string + for rows.Next() { + vals := make([]any, len(cols)) + ptrs := make([]any, len(cols)) + for i := range vals { + ptrs[i] = &vals[i] + } + require.NoError(t, rows.Scan(ptrs...)) + var b strings.Builder + for _, v := range vals { + fmt.Fprintf(&b, "%T:%v|", v, v) + } + out = append(out, b.String()) + } + require.NoError(t, rows.Err()) + return out +} + +func TestUnpackedBlobQueriesMatchRowByRowDefinition(t *testing.T) { + require := require.New(t) + const iterations = 300 + dir := t.TempDir() + st, err := OpenForTest(filepath.Join(dir, "equiv.db")) + require.NoError(err) + defer func() { require.NoError(st.Close()) }() + require.NoError(st.InitSchema()) + ctx := t.Context() + // One connection, so the pragma applies to every statement below. + st.db.SetMaxOpenConns(1) + _, err = st.db.ExecContext(ctx, `PRAGMA foreign_keys = OFF`) + require.NoError(err) + + hexHash := func(r *rand.Rand) string { + const hexd = "0123456789abcdef" + b := make([]byte, 64) + for i := range b { + b[i] = hexd[r.IntN(16)] + } + return string(b) + } + totalContent, totalThumb, nonEmpty := 0, 0, 0 + for iter := range iterations { + r := rand.New(rand.NewPCG(uint64(iter), 0x5eed)) //nolint:gosec // Seeded so a failing iteration reproduces. + _, err := st.db.ExecContext(ctx, `DELETE FROM attachments`) + require.NoError(err) + _, err = st.db.ExecContext(ctx, `DELETE FROM attachment_pack_index`) + require.NoError(err) + + poolSize := 1 + r.IntN(40) + pool := make([]string, poolSize) + for i := range pool { + pool[i] = hexHash(r) + } + hashValue := func() any { + switch r.IntN(20) { + case 0: + return nil + case 1: + return "" + case 2: + return strings.ToUpper(pool[r.IntN(poolSize)]) + case 3: // mixed case + h := []byte(pool[r.IntN(poolSize)]) + for i := range h { + if r.IntN(2) == 0 { + h[i] = strings.ToUpper(string(h[i]))[0] + } + } + return string(h) + case 4: + return "not-a-hash" + case 5: + return " " + pool[r.IntN(poolSize)] + case 6: + return []byte(pool[r.IntN(poolSize)]) // BLOB-typed value + case 7: + return 12345 + default: + return pool[r.IntN(poolSize)] + } + } + pathValue := func(nullable bool) any { + switch k := r.IntN(14); { + case k == 0 && nullable: + return nil + case k == 1: + return "" + case k == 2: + return "http://example.com/x" + case k == 3: + return "HTTPS://Example.com/y" + case k == 4: + return "hTtP://mixed" + case k == 5: + return "ftp://x" + default: + return fmt.Sprintf("%02x/p%d", r.IntN(4), r.IntN(6)) + } + } + rowsN := r.IntN(120) + for i := range rowsN { + var size any + if r.IntN(5) != 0 { + size = r.IntN(1000) + } + var thumbHash, thumbPath any + if r.IntN(3) == 0 { + thumbHash = hashValue() + thumbPath = pathValue(true) + } + _, err := st.db.ExecContext(ctx, `INSERT INTO attachments + (id, message_id, size, content_hash, storage_path, thumbnail_hash, thumbnail_path) + VALUES (?, ?, ?, ?, ?, ?, ?)`, + 1+i*(1+r.IntN(3)), 1+r.IntN(5), size, hashValue(), pathValue(false), thumbHash, thumbPath) + if err != nil && strings.Contains(err.Error(), "UNIQUE") { + continue + } + require.NoError(err) + } + for _, h := range pool { + if r.IntN(2) == 0 { + key := h + if r.IntN(10) == 0 { + key = strings.ToUpper(h) // non-canonical index row + } + _, err := st.db.ExecContext(ctx, `INSERT OR IGNORE INTO attachment_pack_index + (blob_hash, pack_id, pack_offset, stored_len, raw_len, flags, crc32c) + VALUES (?, 'p', 0, 1, 1, 0, 0)`, key) + require.NoError(err) + } + } + if r.IntN(4) == 0 { + _, err := st.db.ExecContext(ctx, `INSERT OR IGNORE INTO attachment_pack_index + (blob_hash, pack_id, pack_offset, stored_len, raw_len, flags, crc32c) + VALUES ('12345', 'p', 0, 1, 1, 0, 0), ('not-a-hash', 'p', 0, 1, 1, 0, 0)`) + require.NoError(err) + } + + wantContent := dumpUnpackedQuery(t, st, rowByRowUnpackedContentSQL) + gotContent := dumpUnpackedQuery(t, st, listUnpackedContentBlobsSQL) + require.Equal(wantContent, gotContent, "content query diverges at iteration %d", iter) + wantThumbnail := dumpUnpackedQuery(t, st, rowByRowUnpackedThumbnailSQL) + gotThumbnail := dumpUnpackedQuery(t, st, listUnpackedThumbnailBlobsSQL) + require.Equal(wantThumbnail, gotThumbnail, "thumbnail query diverges at iteration %d", iter) + totalContent += len(wantContent) + totalThumb += len(wantThumbnail) + if len(wantContent) > 0 && len(wantThumbnail) > 0 { + nonEmpty++ + } + } + // Guard against a generator that stops producing rows to compare. + require.Positive(totalContent) + require.Positive(totalThumb) + require.Positive(nonEmpty) +} diff --git a/internal/store/packs.go b/internal/store/packs.go index a6c0f05d99..b03bde65c7 100644 --- a/internal/store/packs.go +++ b/internal/store/packs.go @@ -694,34 +694,47 @@ func (s *Store) ListUnpackedBlobsContext(ctx context.Context) ([]UnpackedBlob, e return nil } - if err := collect(` + if err := collect(listUnpackedContentBlobsSQL, true); err != nil { + return nil, err + } + if err := collect(listUnpackedThumbnailBlobsSQL, false); err != nil { + return nil, err + } + return blobs, nil +} + +// The unpacked-blob queries find their few candidate hashes from the hash +// indexes alone, then read attachment rows only for those hashes. Testing +// every row against the pack index directly would read every attachment row +// of a large archive to find a handful of new blobs. +const ( + listUnpackedContentBlobsSQL = ` SELECT content_hash, storage_path, COALESCE(MAX(size), -1) FROM attachments - WHERE content_hash IS NOT NULL AND content_hash != '' + WHERE content_hash IN ( + SELECT candidate.content_hash FROM attachments AS candidate + WHERE candidate.content_hash IS NOT NULL AND candidate.content_hash != '' + AND NOT EXISTS (SELECT 1 FROM attachment_pack_index p + WHERE p.blob_hash = LOWER(candidate.content_hash))) AND storage_path IS NOT NULL AND storage_path != '' AND LOWER(storage_path) NOT LIKE 'http://%' AND LOWER(storage_path) NOT LIKE 'https://%' - AND NOT EXISTS (SELECT 1 FROM attachment_pack_index p - WHERE p.blob_hash = LOWER(attachments.content_hash)) GROUP BY content_hash, storage_path - ORDER BY MIN(id), storage_path`, true); err != nil { - return nil, err - } - if err := collect(` + ORDER BY MIN(id), storage_path` + listUnpackedThumbnailBlobsSQL = ` SELECT thumbnail_hash, thumbnail_path FROM attachments - WHERE thumbnail_hash IS NOT NULL AND thumbnail_hash != '' + WHERE thumbnail_hash IN ( + SELECT candidate.thumbnail_hash FROM attachments AS candidate + WHERE candidate.thumbnail_hash IS NOT NULL AND candidate.thumbnail_hash != '' + AND NOT EXISTS (SELECT 1 FROM attachment_pack_index p + WHERE p.blob_hash = LOWER(candidate.thumbnail_hash))) AND thumbnail_path IS NOT NULL AND thumbnail_path != '' AND LOWER(thumbnail_path) NOT LIKE 'http://%' AND LOWER(thumbnail_path) NOT LIKE 'https://%' - AND NOT EXISTS (SELECT 1 FROM attachment_pack_index p - WHERE p.blob_hash = LOWER(attachments.thumbnail_hash)) GROUP BY thumbnail_hash, thumbnail_path - ORDER BY MIN(id), thumbnail_path`, false); err != nil { - return nil, err - } - return blobs, nil -} + ORDER BY MIN(id), thumbnail_path` +) // ListIndexedBlobHashes returns the set of all packed blob hashes. func (s *Store) ListIndexedBlobHashes() (map[string]struct{}, error) {