Add some debug logs and better error message to c1file open/init functions. (#697)

Also check errors when closing files in tests.

Author: ggreer

pkg/dotc1z/c1file.go

@@ -114,8 +114,12 @@ func NewC1File(ctx context.Context, dbFilePath string, opts ...C1FOption) (*C1Fi
 
 	rawDB, err := sql.Open("sqlite", dbFilePath)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("new-c1-file: error opening raw db: %w", err)
 	}
+	l := ctxzap.Extract(ctx)
+	l.Debug("new-c1-file: opened raw db",
+		zap.String("db_file_path", dbFilePath),
+	)
 
 	// Limit to a single connection so idle pool connections don't hold WAL
 	// read locks that prevent PRAGMA wal_checkpoint(TRUNCATE) from completing
@@ -147,7 +151,7 @@ func NewC1File(ctx context.Context, dbFilePath string, opts ...C1FOption) (*C1Fi
 
 	err = c1File.init(ctx)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("new-c1-file: error initializing c1file: %w", err)
 	}
 
 	return c1File, nil
@@ -225,6 +229,11 @@ func NewC1ZFile(ctx context.Context, outputFilePath string, opts ...C1ZOption) (
 	if err != nil {
 		return nil, err
 	}
+	l := ctxzap.Extract(ctx)
+	l.Debug("new-c1z-file: decompressed c1z",
+		zap.String("db_file_path", dbFilePath),
+		zap.String("output_file_path", outputFilePath),
+	)
 
 	var c1fopts []C1FOption
 	for _, pragma := range options.pragmas {
@@ -383,14 +392,18 @@ func (c *C1File) init(ctx context.Context) error {
 
 	err = c.InitTables(ctx)
 	if err != nil {
+		l.Error("c1file-init: error initializing tables", zap.Error(err))
 		return err
 	}
+	l.Debug("c1file-init: initialized tables",
+		zap.String("db_file_path", c.dbFilePath),
+	)
 
 	// // Checkpoint the WAL after migrations. Migrations like backfillGrantExpansionColumn
 	// // can update many rows, filling the WAL. Without a checkpoint, subsequent reads are
 	// // slow because SQLite must scan the WAL hash table for every page read.
 	if _, err = c.db.ExecContext(ctx, "PRAGMA wal_checkpoint(TRUNCATE)"); err != nil {
-		l.Warn("WAL checkpoint after init failed", zap.Error(err))
+		l.Warn("c1file-init: WAL checkpoint after init failed", zap.Error(err))
 	}
 
 	if c.readOnly {
@@ -415,16 +428,17 @@ func (c *C1File) init(ctx context.Context) error {
 		}
 	}
 	if !hasLockingPragma {
+		l.Debug("c1file-init: setting locking mode to EXCLUSIVE", zap.String("db_file_path", c.dbFilePath))
 		_, err = c.db.ExecContext(ctx, "PRAGMA main.locking_mode = EXCLUSIVE")
 		if err != nil {
-			return err
+			return fmt.Errorf("c1file-init: error setting locking mode to EXCLUSIVE: %w", err)
 		}
 	}
 
 	for _, pragma := range c.pragmas {
 		_, err := c.db.ExecContext(ctx, fmt.Sprintf("PRAGMA %s = %s", pragma.name, pragma.value))
 		if err != nil {
-			return err
+			return fmt.Errorf("c1file-init: error setting pragma %s = %s: %w", pragma.name, pragma.value, err)
 		}
 	}
 
@@ -440,16 +454,23 @@ func (c *C1File) InitTables(ctx context.Context) error {
 		return err
 	}
 
+	l := ctxzap.Extract(ctx).With(zap.String("db_file_path", c.dbFilePath))
 	for _, t := range allTableDescriptors {
 		query, args := t.Schema()
 		_, err = c.db.ExecContext(ctx, fmt.Sprintf(query, args...))
 		if err != nil {
-			return err
+			return fmt.Errorf("c1file-init-tables: error initializing table %s: %w", t.Name(), err)
 		}
+		l.Debug("c1file-init-tables: initialized table schema, running migrations",
+			zap.String("table_name", t.Name()),
+		)
 		err = t.Migrations(ctx, c.db)
 		if err != nil {
-			return err
+			return fmt.Errorf("c1file-init-tables: error running migration for table %s: %w", t.Name(), err)
 		}
+		l.Debug("c1file-init-tables: ran migrations for table",
+			zap.String("table_name", t.Name()),
+		)
 	}
 
 	return nil

pkg/dotc1z/grants_test.go

@@ -148,8 +148,12 @@ func TestGrantExpandableSurvivesCloseReopen(t *testing.T) {
 	tmpFile, err := os.CreateTemp("", "test-expansion-reopen-*.c1z")
 	require.NoError(t, err)
 	tmpPath := tmpFile.Name()
-	tmpFile.Close()
-	defer os.Remove(tmpPath)
+	err = tmpFile.Close()
+	require.NoError(t, err)
+	defer func() {
+		err := os.Remove(tmpPath)
+		require.NoError(t, err)
+	}()
 
 	// Phase 1: Create store, write expandable grant, close.
 	func() {
@@ -444,8 +448,12 @@ func TestBackfillMigration_OldSyncGetsExpansionColumn(t *testing.T) {
 
 	tmpFile, err := os.CreateTemp("", "test-backfill-*.c1z")
 	require.NoError(t, err)
-	defer os.Remove(tmpFile.Name())
-	tmpFile.Close()
+	defer func() {
+		err := os.Remove(tmpFile.Name()) //nolint:gosec // G703 -- tmpFile.Name() is created by os.CreateTemp in this test.
+		require.NoError(t, err)
+	}()
+	err = tmpFile.Close()
+	require.NoError(t, err)
 
 	// Step 1: Create a c1z and write grants the "new" way (expansion column populated).
 	c1f, err := NewC1ZFile(ctx, tmpFile.Name())
@@ -636,7 +644,8 @@ func setupTestC1Z(ctx context.Context, t *testing.T) (*C1File, string, func()) {
 	t.Helper()
 	tmpFile, err := os.CreateTemp("", "test-grants-*.c1z")
 	require.NoError(t, err)
-	tmpFile.Close()
+	err = tmpFile.Close()
+	require.NoError(t, err)
 
 	c1f, err := NewC1ZFile(ctx, tmpFile.Name())
 	require.NoError(t, err)
@@ -657,9 +666,10 @@ func setupTestC1Z(ctx context.Context, t *testing.T) (*C1File, string, func()) {
 	require.NoError(t, c1f.PutEntitlements(ctx, ent1, ent2))
 
 	cleanup := func() {
-		_ = c1f.Close(ctx)
-		// #nosec G703 -- tmpFile.Name() is created by os.CreateTemp in this test.
-		os.Remove(tmpFile.Name())
+		err := c1f.Close(ctx)
+		require.NoError(t, err)
+		err = os.Remove(tmpFile.Name()) //nolint:gosec // G703 -- tmpFile.Name() is created by os.CreateTemp in this test.
+		require.NoError(t, err)
 	}
 	return c1f, syncID, cleanup
 }