[#7836] fixed migration logs write deadlock and added app.ClearBootstrap/OnClearBootstrap helpers

core/base_test.go

@@ -65,7 +65,7 @@ func TestBaseAppBootstrap(t *testing.T) {
 	app := core.NewBaseApp(core.BaseAppConfig{
 		DataDir: testDataDir,
 	})
-	defer app.ResetBootstrapState()
+	defer app.ClearBootstrap()
 
 	if app.IsBootstrapped() {
 		t.Fatal("Didn't expect the application to be bootstrapped.")
@@ -115,7 +115,7 @@ func TestBaseAppBootstrap(t *testing.T) {
 	runNilChecks(nilChecksBeforeReset)
 
 	// reset
-	if err := app.ResetBootstrapState(); err != nil {
+	if err := app.ClearBootstrap(); err != nil {
 		t.Fatal(err)
 	}
 
@@ -141,7 +141,7 @@ func TestNewBaseAppTx(t *testing.T) {
 	app := core.NewBaseApp(core.BaseAppConfig{
 		DataDir: testDataDir,
 	})
-	defer app.ResetBootstrapState()
+	defer app.ClearBootstrap()
 
 	if err := app.Bootstrap(); err != nil {
 		t.Fatal(err)
@@ -185,7 +185,7 @@ func TestBaseAppNewMailClient(t *testing.T) {
 		DataDir:       testDataDir,
 		EncryptionEnv: "pb_test_env",
 	})
-	defer app.ResetBootstrapState()
+	defer app.ClearBootstrap()
 
 	client1 := app.NewMailClient()
 	m1, ok := client1.(*mailer.Sendmail)
@@ -215,7 +215,7 @@ func TestBaseAppNewFilesystem(t *testing.T) {
 	app := core.NewBaseApp(core.BaseAppConfig{
 		DataDir: testDataDir,
 	})
-	defer app.ResetBootstrapState()
+	defer app.ClearBootstrap()
 
 	// local
 	local, localErr := app.NewFilesystem()
@@ -244,7 +244,7 @@ func TestBaseAppNewBackupsFilesystem(t *testing.T) {
 	app := core.NewBaseApp(core.BaseAppConfig{
 		DataDir: testDataDir,
 	})
-	defer app.ResetBootstrapState()
+	defer app.ClearBootstrap()
 
 	// local
 	local, localErr := app.NewBackupsFilesystem()
@@ -266,74 +266,175 @@ func TestBaseAppNewBackupsFilesystem(t *testing.T) {
 	}
 }
 
+const logsThreshold = 200
+
+func assertLogsCount(t *testing.T, app core.App, expected int) {
+	var total int
+
+	err := app.LogQuery().Select("count(*)").Row(&total)
+	if err != nil {
+		t.Fatalf("Failed to fetch total logs: %v", err)
+	}
+
+	if total != expected {
+		t.Fatalf("Expected %d log(s), got %d", expected, total)
+	}
+}
+
 func TestBaseAppLoggerWrites(t *testing.T) {
 	t.Parallel()
 
+	// note: outside of synctest because the bootstrap tickers could deadlock
 	app, _ := tests.NewTestApp()
 	defer app.Cleanup()
 
-	// reset
-	if err := app.DeleteOldLogs(time.Now()); err != nil {
+	// clear old logs
+	err := app.DeleteOldLogs(time.Now())
+	if err != nil {
 		t.Fatal(err)
 	}
 
-	const logsThreshold = 200
-
-	totalLogs := func(app core.App, t *testing.T) int {
-		var total int
-
-		err := app.LogQuery().Select("count(*)").Row(&total)
-		if err != nil {
-			t.Fatalf("Failed to fetch total logs: %v", err)
-		}
-
-		return total
-	}
-
 	t.Run("disabled logs retention", func(t *testing.T) {
-		app.Settings().Logs.MaxDays = 0
+		synctest.Test(t, func(t *testing.T) {
+			app.Settings().Logs.MaxDays = 0
 
-		for i := 0; i < logsThreshold+1; i++ {
-			app.Logger().Error("test")
-		}
+			for i := 0; i < logsThreshold+1; i++ {
+				app.Logger().Error("test")
+			}
 
-		if total := totalLogs(app, t); total != 0 {
-			t.Fatalf("Expected no logs, got %d", total)
-		}
+			// short delay for the non-blocking write goroutine
+			synctest.Sleep(time.Nanosecond)
+
+			assertLogsCount(t, app, 0)
+		})
 	})
 
 	t.Run("test batch logs writes", func(t *testing.T) {
 		synctest.Test(t, func(t *testing.T) {
-			app.Settings().Logs.MaxDays = 1
+			app.Settings().Logs.MaxDays = 2
 
 			for i := 0; i < logsThreshold-1; i++ {
 				app.Logger().Error("test")
 			}
 
-			if total := totalLogs(app, t); total != 0 {
-				t.Fatalf("Expected no logs, got %d", total)
-			}
+			// short delay for the non-blocking write goroutine
+			synctest.Sleep(time.Nanosecond)
 
-			// should trigger batch write
+			// below threshold
+			assertLogsCount(t, app, 0)
+
+			// threshold reached -> should trigger batch write
 			app.Logger().Error("test")
 
-			// should be added for the next batch write
+			// should be skipped from this batch and added for the next
 			app.Logger().Error("test")
 
-			if total := totalLogs(app, t); total != logsThreshold {
-				t.Fatalf("Expected %d logs, got %d", logsThreshold, total)
-			}
+			// short delay for the non-blocking write goroutine
+			synctest.Sleep(time.Nanosecond)
 
-			// wait for 3 secs to check the timer trigger
-			synctest.Sleep(3000 * time.Millisecond)
+			assertLogsCount(t, app, logsThreshold)
 
-			if total := totalLogs(app, t); total != logsThreshold {
-				t.Fatalf("Expected %d logs, got %d", logsThreshold, total)
-			}
+			// note: we can't test the flush timer here because the ticker
+			// was started out of the synctest buble to avoid deadlocks
+			// (see TestBaseAppLoggerWritesAwaited for a flaky but real timer test)
 		})
 	})
 }
 
+func TestBaseAppLoggerWritesAwaited(t *testing.T) {
+	t.Parallel()
+
+	app, _ := tests.NewTestApp()
+	defer app.Cleanup()
+
+	// clear old logs
+	err := app.DeleteOldLogs(time.Now())
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// enable logs persistence
+	app.Settings().Logs.MaxDays = 1
+	err = app.Save(app.Settings())
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	t.Run("flush on timer tick", func(t *testing.T) {
+		timeout := time.After(5 * time.Second)
+		done := make(chan struct{})
+
+		logsHook := app.OnModelAfterCreateSuccess("_logs")
+		hookId := logsHook.BindFunc(func(e *core.ModelEvent) error {
+			done <- struct{}{}
+			return e.Next()
+		})
+		defer logsHook.Unbind(hookId)
+
+		app.Logger().Error("test")
+
+		// short wait to ensure that there is no non-blocking write
+		time.Sleep(500 * time.Millisecond)
+
+		assertLogsCount(t, app, 0)
+
+		// wait for the ticker to write the db record
+		select {
+		case <-timeout:
+			t.Fatal("ticker wait timeout")
+		case <-done:
+		}
+
+		assertLogsCount(t, app, 1)
+	})
+
+	t.Run("before ClearBootstrap flush", func(t *testing.T) {
+		app.Logger().Error("test")
+
+		app.Bootstrap()
+
+		assertLogsCount(t, app, 2)
+	})
+
+	t.Run("batch flush inside aux transaction shouldn't hang", func(t *testing.T) {
+		timeout := time.After(1 * time.Second)
+		done := make(chan struct{})
+		totalCreated := 0
+
+		logsHook := app.OnModelAfterCreateSuccess("_logs")
+		hookId := logsHook.BindFunc(func(e *core.ModelEvent) error {
+			totalCreated++
+			if totalCreated == 200 {
+				done <- struct{}{}
+			}
+			return e.Next()
+		})
+		defer logsHook.Unbind(hookId)
+
+		app.AuxRunInTransaction(func(txApp core.App) error {
+			for range logsThreshold {
+				txApp.Logger().Error("test")
+			}
+
+			return nil
+		})
+
+		// wait for the non-blocking write
+		select {
+		case <-timeout:
+			t.Fatal("non-blocking write timeout")
+		case <-done:
+		}
+
+		assertLogsCount(t, app, 202)
+
+		// force clear to ensure that there are no other logs
+		app.Bootstrap()
+
+		assertLogsCount(t, app, 202)
+	})
+}
+
 func TestBaseAppRefreshSettingsLoggerMinLevelEnabled(t *testing.T) {
 	scenarios := []struct {
 		name  string
@@ -373,7 +474,7 @@ func TestBaseAppRefreshSettingsLoggerMinLevelEnabled(t *testing.T) {
 				DataDir: testDataDir,
 				IsDev:   s.isDev,
 			})
-			defer app.ResetBootstrapState()
+			defer app.ClearBootstrap()
 
 			if err := app.Bootstrap(); err != nil {
 				t.Fatal(err)