Hold runMu in internal/cli tests that log outside a CLI run (closes #210)

A CLI run under runMu points the process-global logger at its own
buffers, so a line another test logged outside runMu could land in that
run's output. TestCheckQuietShowsFailedFiles caught one: a "loaded
manifest" line in the stderr of a passing check -q run.

The test helpers that scan or load a manifest now hold runMu
themselves, and so do the remaining direct loads and scans, the
recordEntry call and the retrying download. Two dotfile tests use
manifestPaths instead of loading the manifest themselves.

Judgement call: a downloadFile call that gets its answer on the first
request does not log, so those calls are left as they are.

Model: opus-5-5

docs/FORMAT.md

@@ -75,15 +75,15 @@ After decompressing `innerMessage`, the result is a serialized `MFFile`
 
 Each file entry contains:
 
-| Field      | Number | Type                      | Description                         |
-| ---------- | ------ | ------------------------- | ----------------------------------- |
-| `path`     | 1      | string                    | Relative file path (see Path Rules) |
-| `size`     | 2      | int64                     | File size in bytes                  |
-| `hashes`   | 3      | repeated `MFFileChecksum` | At least one hash required          |
-| `mimeType` | 301    | string (optional)         | MIME type                           |
-| `mtime`    | 302    | Timestamp (optional)      | Modification time                   |
-| `ctime`    | 303    | Timestamp (optional)      | Change time (inode metadata change) |
-| `mode`     | 304    | uint32                    | Permission bits (see File Mode)     |
+| Field      | Number | Type                      | Description                                                   |
+| ---------- | ------ | ------------------------- | ------------------------------------------------------------- |
+| `path`     | 1      | string                    | Relative file path (see Path Rules)                           |
+| `size`     | 2      | int64                     | File size in bytes                                            |
+| `hashes`   | 3      | repeated `MFFileChecksum` | At least one hash required; readers reject an entry with none |
+| `mimeType` | 301    | string (optional)         | MIME type                                                     |
+| `mtime`    | 302    | Timestamp (optional)      | Modification time                                             |
+| `ctime`    | 303    | Timestamp (optional)      | Change time (inode metadata change)                           |
+| `mode`     | 304    | uint32                    | Permission bits (see File Mode)                               |
 
 ## File Mode
 
@@ -174,6 +174,10 @@ also refuses a manifest whose `signingPubKey` holds a DSA key or subkey, or any
 secret key or subkey, since checking the self-signatures of a DSA key or the
 numbers of a secret key can take hours when those numbers are very large.
 
+A signing key that has expired does not make the signature bad, because a
+manifest outlives its key. A signature past its own expiry time is not good,
+whether or not the key has expired too.
+
 ## Deterministic Serialization
 
 By default, manifests are generated deterministically:

internal/cli/entry_test.go

@@ -771,13 +771,9 @@ func TestGenerateExcludesDotfilesByDefault(t *testing.T) {
 	assert.True(t, exists)
 
 	// Verify manifest only has 1 file (the non-dotfile)
-	manifest, err := mfer.NewManifestFromFile(&mfer.ManifestFromFileOptions{
-		Path: testMF,
-		Fs:   fs,
-	})
-	require.NoError(t, err)
-	assert.Len(t, manifest.Files(), 1)
-	assert.Equal(t, "file1.txt", manifest.Files()[0].GetPath())
+	paths := manifestPaths(t, fs, testMF)
+	require.Len(t, paths, 1)
+	assert.Equal(t, "file1.txt", paths[0])
 }
 
 func TestGenerateWithIncludeDotfiles(t *testing.T) {
@@ -798,12 +794,7 @@ func TestGenerateWithIncludeDotfiles(t *testing.T) {
 	require.Equal(t, 0, exitCode)
 
 	// Verify manifest has 2 files (including dotfile)
-	manifest, err := mfer.NewManifestFromFile(&mfer.ManifestFromFileOptions{
-		Path: testMF,
-		Fs:   fs,
-	})
-	require.NoError(t, err)
-	assert.Len(t, manifest.Files(), 2)
+	assert.Len(t, manifestPaths(t, fs, testMF), 2)
 }
 
 func TestMultipleInputPaths(t *testing.T) {
@@ -1224,6 +1215,11 @@ func TestGenerateFailsWithoutForceWhenOutputExists(t *testing.T) {
 func manifestPaths(t *testing.T, fs afero.Fs, path string) []string {
 	t.Helper()
 
+	// Loading a manifest logs to the process-global logger, so serialize
+	// with the CLI runs.
+	runMu.Lock()
+	defer runMu.Unlock()
+
 	manifest, err := mfer.NewManifestFromFile(&mfer.ManifestFromFileOptions{
 		Path: path,
 		Fs:   fs,

internal/cli/errmsg_test.go

@@ -54,6 +54,11 @@ func runLocked(fn func() error) error {
 func unsignedChecker(t *testing.T) *mfer.Checker {
 	t.Helper()
 
+	// The scan and the manifest load log to the process-global logger, so
+	// serialize with the CLI runs.
+	runMu.Lock()
+	defer runMu.Unlock()
+
 	fs := afero.NewMemMapFs()
 	require.NoError(t, fs.MkdirAll("/d", 0o755))
 	require.NoError(t, afero.WriteFile(fs, "/d/f.txt", []byte("hi"), 0o644))
@@ -183,6 +188,11 @@ func signedManifest(t *testing.T, files map[string][]byte) []byte {
 func signedChecker(t *testing.T, manifest []byte) *mfer.Checker {
 	t.Helper()
 
+	// Loading a manifest logs to the process-global logger, so serialize
+	// with the CLI runs.
+	runMu.Lock()
+	defer runMu.Unlock()
+
 	fs := afero.NewMemMapFs()
 	require.NoError(t, afero.WriteFile(fs, "/index.mf", manifest, 0o644))
 

internal/cli/export_test.go

@@ -20,6 +20,11 @@ const testCmdExport = "export"
 func buildTestManifest(t *testing.T, files map[string][]byte) []byte {
 	t.Helper()
 
+	// The scan logs to the process-global logger, so serialize with the
+	// CLI runs.
+	runMu.Lock()
+	defer runMu.Unlock()
+
 	sourceFs := afero.NewMemMapFs()
 	for path, content := range files {
 		require.NoError(t, sourceFs.MkdirAll("/", 0o755))

internal/cli/fetch_test.go

@@ -171,6 +171,11 @@ func TestResolveManifestURL(t *testing.T) {
 func scanToManifest(t *testing.T, sourceFs afero.Fs) []byte {
 	t.Helper()
 
+	// The scan logs to the process-global logger, so serialize with the
+	// CLI runs.
+	runMu.Lock()
+	defer runMu.Unlock()
+
 	s := mfer.NewScannerWithOptions(&mfer.ScannerOptions{Fs: sourceFs})
 	require.NoError(t, s.EnumerateFS(sourceFs, "/", nil))
 
@@ -314,8 +319,11 @@ func TestFetchFromHTTP(t *testing.T) {
 	// Change to a fresh destination directory for the test
 	destDir := chdirTemp(t)
 
-	// Parse the manifest to get file entries
+	// Parse the manifest to get file entries. Loading a manifest logs to
+	// the process-global logger.
+	runMu.Lock()
 	manifest, err := mfer.NewManifestFromReader(bytes.NewReader(manifestData))
+	runMu.Unlock()
 	require.NoError(t, err)
 
 	files := manifest.Files()
@@ -365,7 +373,10 @@ func TestFetchHashMismatch(t *testing.T) {
 	// Generate and parse manifest
 	manifestData := scanToManifest(t, sourceFs)
 
+	// Loading a manifest logs to the process-global logger.
+	runMu.Lock()
 	manifest, err := mfer.NewManifestFromReader(bytes.NewReader(manifestData))
+	runMu.Unlock()
 	require.NoError(t, err)
 
 	files := manifest.Files()
@@ -411,7 +422,10 @@ func TestFetchSizeMismatch(t *testing.T) {
 	// Generate and parse manifest
 	manifestData := scanToManifest(t, sourceFs)
 
+	// Loading a manifest logs to the process-global logger.
+	runMu.Lock()
 	manifest, err := mfer.NewManifestFromReader(bytes.NewReader(manifestData))
+	runMu.Unlock()
 	require.NoError(t, err)
 
 	files := manifest.Files()
@@ -523,7 +537,10 @@ func TestFetchProgress(t *testing.T) {
 	// Generate and parse manifest
 	manifestData := scanToManifest(t, sourceFs)
 
+	// Loading a manifest logs to the process-global logger.
+	runMu.Lock()
 	manifest, err := mfer.NewManifestFromReader(bytes.NewReader(manifestData))
+	runMu.Unlock()
 	require.NoError(t, err)
 
 	files := manifest.Files()
@@ -897,9 +914,12 @@ func TestGetStopsWaitingWhenCanceled(t *testing.T) {
 //nolint:paralleltest // changes the process-global working directory
 func TestDownloadFileRetriesToSuccess(t *testing.T) {
 	content := []byte("the whole file, every byte of it")
+	manifestData := manifestOf(t, map[string][]byte{testFileTxt: content})
 
-	manifest, err := mfer.NewManifestFromReader(bytes.NewReader(
-		manifestOf(t, map[string][]byte{testFileTxt: content})))
+	// Loading a manifest logs to the process-global logger.
+	runMu.Lock()
+	manifest, err := mfer.NewManifestFromReader(bytes.NewReader(manifestData))
+	runMu.Unlock()
 	require.NoError(t, err)
 
 	var requests atomic.Int32
@@ -922,8 +942,11 @@ func TestDownloadFileRetriesToSuccess(t *testing.T) {
 
 	chdirTemp(t)
 
-	err = downloadFile(context.Background(), testClient(),
-		server.URL+"/"+testFileTxt, ".", testFileTxt, manifest.Files()[0], nil)
+	// downloadFile logs each retry to the process-global logger.
+	err = runLocked(func() error {
+		return downloadFile(context.Background(), testClient(),
+			server.URL+"/"+testFileTxt, ".", testFileTxt, manifest.Files()[0], nil)
+	})
 	require.NoError(t, err)
 	assert.Equal(t, int32(3), requests.Load())
 
@@ -1404,14 +1427,18 @@ func TestFetchSetsRecordedMode(t *testing.T) {
 		require.NoError(t, afero.WriteFile(sourceFs, "/"+p, content, modes[p]))
 	}
 
-	scanner := mfer.NewScannerWithOptions(&mfer.ScannerOptions{
-		Fs:                 sourceFs,
-		IncludePermissions: true,
-	})
-	require.NoError(t, scanner.EnumerateFS(sourceFs, "/", nil))
-
 	var manifest bytes.Buffer
-	require.NoError(t, scanner.ToManifest(context.Background(), &manifest, nil))
+
+	// The scan logs to the process-global logger.
+	require.NoError(t, runLocked(func() error {
+		scanner := mfer.NewScannerWithOptions(&mfer.ScannerOptions{
+			Fs:                 sourceFs,
+			IncludePermissions: true,
+		})
+		require.NoError(t, scanner.EnumerateFS(sourceFs, "/", nil))
+
+		return scanner.ToManifest(context.Background(), &manifest, nil)
+	}))
 
 	tree := fetchTestHandler(manifest.Bytes(), files)
 

internal/cli/freshen.go

@@ -28,9 +28,15 @@ const (
 	scanProgressInterval = 100
 )
 
-// errEntryMissingMtime indicates a manifest entry that carries no
-// modification time where one is required to carry it forward unchanged.
-var errEntryMissingMtime = errors.New("manifest entry has no mtime")
+var (
+	// errEntryMissingMtime indicates a manifest entry that carries no
+	// modification time where one is required to carry it forward unchanged.
+	errEntryMissingMtime = errors.New("manifest entry has no mtime")
+
+	// errEntryMissingHash indicates a manifest entry that carries no hash
+	// to carry forward.
+	errEntryMissingHash = errors.New("manifest entry has no hash")
+)
 
 // FreshenStatus contains progress information for the freshen operation.
 type FreshenStatus struct {
@@ -644,6 +650,8 @@ func addFileToBuilder(
 // Entries reach this path only when recordEntry classified them as
 // unchanged, which requires a recorded mtime, so an absent mtime here is
 // an error rather than something to paper over with the Unix epoch.
+// Loading refuses an entry with no hash; one that got here anyway is an
+// error too, not a file to leave out of the manifest.
 func addExistingToBuilder(b *mfer.Builder, entry *mfer.MFFilePath) error {
 	mtime, ok := entryMtime(entry)
 	if !ok {
@@ -651,7 +659,7 @@ func addExistingToBuilder(b *mfer.Builder, entry *mfer.MFFilePath) error {
 	}
 
 	if len(entry.GetHashes()) == 0 {
-		return nil
+		return fmt.Errorf("%w: %s", errEntryMissingHash, entry.GetPath())
 	}
 
 	err := b.AddFileWithHash(mfer.RelFilePath(entry.GetPath()),

internal/cli/freshen_test.go

@@ -70,6 +70,11 @@ func runFreshen(t *testing.T, fs afero.Fs, root, manifestPath string) {
 func manifestFiles(t *testing.T, fs afero.Fs, path string) []*mfer.MFFilePath {
 	t.Helper()
 
+	// Loading a manifest logs to the process-global logger, so serialize
+	// with the CLI runs.
+	runMu.Lock()
+	defer runMu.Unlock()
+
 	manifest, err := mfer.NewManifestFromFile(&mfer.ManifestFromFileOptions{
 		Path: path,
 		Fs:   fs,
@@ -436,7 +441,11 @@ func TestFreshenRecordEntryMtimePresence(t *testing.T) {
 			s := &freshenScanner{
 				existingByPath: map[string]*mfer.MFFilePath{relPath: tc.entry},
 			}
+
+			// recordEntry logs to the process-global logger.
+			runMu.Lock()
 			s.recordEntry(relPath, info)
+			runMu.Unlock()
 
 			require.Len(t, s.entries, 1)
 			assert.Equal(t, tc.needsHash, s.entries[0].needsHash)
@@ -471,6 +480,24 @@ func TestFreshenAddExistingRejectsMissingMtime(t *testing.T) {
 	assert.Contains(t, err.Error(), "file1.txt")
 }
 
+// TestFreshenAddExistingRejectsMissingHash pins that an entry with no hash
+// is an error rather than a file left out of the rebuilt manifest.
+func TestFreshenAddExistingRejectsMissingHash(t *testing.T) {
+	t.Parallel()
+
+	b := mfer.NewBuilder()
+	entry := &mfer.MFFilePath{
+		Path:  "data.bin",
+		Size:  8,
+		Mtime: &mfer.Timestamp{Seconds: 1_700_000_000},
+	}
+
+	err := addExistingToBuilder(b, entry)
+	require.ErrorIs(t, err, errEntryMissingHash)
+	assert.Contains(t, err.Error(), "data.bin")
+	assert.Zero(t, b.FileCount())
+}
+
 // TestFreshenAddExistingRejectsShortHash pins that an existing manifest
 // entry whose hash the builder refuses is reported as a problem with the
 // manifest, with the command that fixes it.

mfer/deserialize.go

@@ -27,6 +27,7 @@ var (
 	errUUIDMismatch         = errors.New("outer and inner UUID mismatch")
 	errInvalidFileFormat    = errors.New("invalid file format")
 	errInvalidManifestPath  = errors.New("invalid file entry")
+	errEntryMissingHash     = errors.New("file entry has no hash")
 	errDecodedTooLarge      = errors.New("too much memory needed")
 	errSignerNotSigningKey  = errors.New(
 		"signer is not the fingerprint of the key that made the signature")
@@ -293,7 +294,8 @@ func (m *manifest) deserializeInner() error {
 	// untrusted .mf. Reject loudly on the first offender rather than
 	// dropping entries, which would let a hostile manifest hide files from a
 	// check. A path listed twice is refused too: check would check the one
-	// file against both entries.
+	// file against both entries. So is an entry with no hash: there is
+	// nothing to check the file against.
 	seen := make(map[string]bool, len(m.pbInner.GetFiles()))
 
 	for _, f := range m.pbInner.GetFiles() {
@@ -302,6 +304,10 @@ func (m *manifest) deserializeInner() error {
 			return fmt.Errorf("%w: %w", errInvalidManifestPath, err)
 		}
 
+		if len(f.GetHashes()) == 0 {
+			return fmt.Errorf("%w: %q", errEntryMissingHash, f.GetPath())
+		}
+
 		if seen[f.GetPath()] {
 			return fmt.Errorf("%w %q", errDuplicatePath, f.GetPath())
 		}

mfer/deserialize_path_test.go

@@ -165,6 +165,24 @@ func TestDeserializeRefusesPathListedTwice(t *testing.T) {
 	}
 }
 
+// A manifest holding a file entry with no hash is refused as it is loaded,
+// naming the path: there is nothing to check the file against.
+func TestDeserializeRefusesEntryWithNoHash(t *testing.T) {
+	t.Parallel()
+
+	id := uuid.NewV4()
+	inner, err := proto.Marshal(&MFFile{
+		Version: MFFile_VERSION_ONE,
+		Files:   []*MFFilePath{{Path: "x", Size: 1}},
+		Uuid:    id[:],
+	})
+	require.NoError(t, err)
+
+	_, err = NewManifestFromReader(bytes.NewReader(wrapInner(t, id, inner)))
+	require.ErrorIs(t, err, errEntryMissingHash)
+	require.EqualError(t, err, `file entry has no hash: "x"`)
+}
+
 // Entries of a path, an empty hash, an empty MIME type and empty modification
 // and change times are counted at 432 bytes each (176 + 112 + 16 + 64 + 64)
 // and take 16 bytes plus the path to encode. A 37-character path makes that
@@ -229,6 +247,8 @@ func TestDeserializeDropsUnknownFields(t *testing.T) {
 
 	entry := protowire.AppendTag(nil, 1, protowire.BytesType) // MFFilePath.path
 	entry = protowire.AppendString(entry, "a")
+	entry = protowire.AppendTag(entry, 3, protowire.BytesType) // MFFilePath.hashes
+	entry = protowire.AppendBytes(entry, nil)
 	entry = append(entry, unknown...)
 
 	id := uuid.NewV4()

mfer/openpgp.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"slices"
 	"strings"
+	"time"
 
 	"github.com/ProtonMail/go-crypto/openpgp"
 	"github.com/ProtonMail/go-crypto/openpgp/armor"
@@ -242,10 +243,10 @@ func fingerprint(key *openpgp.Entity) string {
 	return strings.ToUpper(hex.EncodeToString(key.PrimaryKey.Fingerprint))
 }
 
-// verifySignature checks that signature is one good OpenPGP signature
-// over data, made by the one primary key in pubKey or one of its subkeys,
-// and returns that primary key's fingerprint. signature and pubKey may each
-// be armored or binary.
+// verifySignature checks that signature is one good, unexpired OpenPGP
+// signature over data, made by the one primary key in pubKey or one of its
+// subkeys, and returns that primary key's fingerprint. signature and pubKey
+// may each be armored or binary.
 func verifySignature(data, signature, pubKey []byte) (string, error) {
 	key, err := readOneKey(pubKey, "embedded public key block", true)
 	if err != nil {
@@ -266,10 +267,16 @@ func verifySignature(data, signature, pubKey []byte) (string, error) {
 		return "", fmt.Errorf("%w, found %d", errNotOneSignature, sigs)
 	}
 
-	_, err = openpgp.CheckDetachedSignature(openpgp.EntityList{key},
+	sig, _, err := openpgp.VerifyDetachedSignature(openpgp.EntityList{key},
 		bytes.NewReader(data), bytes.NewReader(sigData), nil)
 	// A manifest outlives its signing key, so a signature by a key that
-	// has expired since is still good.
+	// has expired since is still good, unless the signature has expired
+	// itself. The library does not check that once it finds the key
+	// expired.
+	if errors.Is(err, pgperrors.ErrKeyExpired) && sig.SigExpired(time.Now()) {
+		err = pgperrors.ErrSignatureExpired
+	}
+
 	if err != nil && !errors.Is(err, pgperrors.ErrKeyExpired) {
 		return "", fmt.Errorf("verify signature: %w", err)
 	}

mfer/openpgp_test.go

@@ -18,6 +18,7 @@ import (
 	"github.com/ProtonMail/go-crypto/openpgp"
 	"github.com/ProtonMail/go-crypto/openpgp/armor"
 	"github.com/ProtonMail/go-crypto/openpgp/elgamal"
+	pgperrors "github.com/ProtonMail/go-crypto/openpgp/errors"
 	"github.com/ProtonMail/go-crypto/openpgp/packet"
 	"github.com/spf13/afero"
 	"github.com/stretchr/testify/assert"
@@ -416,8 +417,10 @@ func TestVerifySignature(t *testing.T) {
 	assert.Error(t, err)
 }
 
-// TestVerifySignatureKeyExpiredSince verifies a signature made in 2020 by
-// a key that expired a day after it was made. The signature is still good.
+// TestVerifySignatureKeyExpiredSince verifies two signatures made in 2020
+// by a key that expired a day after it was made. A signature with no
+// expiry time is still good. One that expired an hour after it was made is
+// refused, although the key has expired too.
 func TestVerifySignatureKeyExpiredSince(t *testing.T) {
 	t.Parallel()
 
@@ -429,9 +432,14 @@ func TestVerifySignatureKeyExpiredSince(t *testing.T) {
 	key := newTestKey(t, config)
 	data := []byte("signed in 2020")
 
-	var sig bytes.Buffer
+	var sig, expiringSig bytes.Buffer
 
 	require.NoError(t, openpgp.ArmoredDetachSign(&sig, key, bytes.NewReader(data), config))
+	require.NoError(t, openpgp.ArmoredDetachSign(&expiringSig, key,
+		bytes.NewReader(data), &packet.Config{
+			Time:            config.Time,
+			SigLifetimeSecs: uint32(time.Hour.Seconds()),
+		}))
 
 	pubKey, err := armoredPublicKey(key)
 	require.NoError(t, err)
@@ -439,6 +447,9 @@ func TestVerifySignatureKeyExpiredSince(t *testing.T) {
 	signer, err := verifySignature(data, sig.Bytes(), pubKey)
 	require.NoError(t, err)
 	assert.Equal(t, fingerprint(key), signer)
+
+	_, err = verifySignature(data, expiringSig.Bytes(), pubKey)
+	require.ErrorIs(t, err, pgperrors.ErrSignatureExpired)
 }
 
 func TestManifestSignatureVerification(t *testing.T) {