Reduce the amount of log messages with TRACKER_VERBOSITY=1

I want to enable TRACKER_VERBOSITY=1 in CI, so that we have more
detailed logs with tests fail in CI. However, there are quite a lot
of unnecessary and repeated messages from libtracker-data at this
level.

Example before:

    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Setting database locations
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Checking database directories exist
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Checking whether database files exist
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Could not find database file:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db', reindex will be forced
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Cleaning up database files for reindex
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Removing all database/storage files
    (tracker-store:22279): Tracker-INFO: 19:09:04.552:   Removing database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Creating database files, this may take a few moments...
    (tracker-store:22279): Tracker-INFO: 19:09:04.552: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.553:   Setting page size to 8192
    (tracker-store:22279): Tracker-INFO: 19:09:04.553:   Setting cache size to 250
    (tracker-store:22279): Tracker-INFO: 19:09:04.553: Closed sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.553: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.554:   Setting page size to 8192
    (tracker-store:22279): Tracker-INFO: 19:09:04.554:   Setting cache size to 250
    (tracker-store:22279): Tracker-INFO: 19:09:04.554: Loading databases files...
    (tracker-store:22279): Tracker-INFO: 19:09:04.554: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.555:   Setting page size to 8192
    (tracker-store:22279): Tracker-INFO: 19:09:04.555:   Setting cache size to 250
    (tracker-store:22279): Tracker-INFO: 19:09:04.555: Closed sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.582: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:04.582:   Setting page size to 8192
    (tracker-store:22279): Tracker-INFO: 19:09:04.604:   Setting cache size to 250
    (tracker-store:22279): Tracker-INFO: 19:09:05.671: Saving DB locale as: 'en_GB.utf8'
    (tracker-store:22279): Tracker-INFO: 19:09:05.673: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db'
    (tracker-store:22279): Tracker-INFO: 19:09:05.711:   Setting page size to 8192
    (tracker-store:22279): Tracker-INFO: 19:09:05.711:   Setting cache size to 250trackertestutils.dbusdaemon.stdout: dbus-daemon[23534]: [session uid=1000 pid=23534] The maximum number of pending replies for ":1.1" (uid=1000 pid=23543 comm="tests/functional-tests/ipc/test-bus-query-cancella" label="unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023") has been reached (max_replies_per_connection=128)

Example after:

    (tracker-store:14505): Tracker-INFO: 19:03:50.256: Could not find database file:'/tmp/tracker-test-ask61juj/cache/tracker/meta.db', reindex will be forced
    (tracker-store:14505): Tracker-INFO: 19:03:50.257: Removing all files for database /tmp/tracker-test-ask61juj/cache/tracker/meta.db
    (tracker-store:14505): Tracker-INFO: 19:03:50.257: Creating database files for /tmp/tracker-test-ask61juj/cache/tracker/meta.db...
    (tracker-store:14505): Tracker-INFO: 19:03:50.298: Loading files for database /tmp/tracker-test-ask61juj/cache/tracker/meta.db...
    (tracker-store:14505): Tracker-INFO: 19:03:51.227: Saving DB locale as: 'en_GB.utf8'

The size of the meson-logs/testlog.txt with TRACKER_VERBOSITY=1 reduces
from 436KiB to 250KiB.

We also now log a g_info() message when doing a blocking
sqlite3_wal_checkpoint_v2() call. This may help with debugging
the test timeouts that happen on certain CI runners (e.g.
https://gitlab.gnome.org/GNOME/tracker/issues/145).

2 files changed, 18 insertions, 17 deletions

diff --git a/src/libtracker-data/tracker-db-interface-sqlite.c b/src/libtracker-data/tracker-db-interface-sqlite.c
index a789fe963..9bbb7b64f 100644
--- a/src/libtracker-data/tracker-db-interface-sqlite.c
+++ b/src/libtracker-data/tracker-db-interface-sqlite.c
@@ -1933,7 +1933,7 @@ open_database (TrackerDBInterface  *db_interface,
 		             "Could not open sqlite3 database:'%s': %s", db_interface->filename, str);
 		return;
 	} else {
-		g_info ("Opened sqlite3 database:'%s'", db_interface->filename);
+		g_debug ("Opened sqlite3 database:'%s'", db_interface->filename);
 	}
 
 	/* Set our unicode collation function */
@@ -2380,6 +2380,11 @@ tracker_db_interface_sqlite_wal_checkpoint (TrackerDBInterface  *interface,
                                             GError             **error)
 {
 	int return_val;
+	GLogLevelFlags log_level;
+
+	log_level = blocking ? G_LOG_LEVEL_INFO : G_LOG_LEVEL_DEBUG;
+
+	g_log (G_LOG_DOMAIN, log_level, "Checkpointing database (%s)...", blocking ? "blocking" : "non-blocking");
 
 	return_val = sqlite3_wal_checkpoint_v2 (interface->db, NULL,
 	                                        blocking ? SQLITE_CHECKPOINT_FULL : SQLITE_CHECKPOINT_PASSIVE,
@@ -2393,6 +2398,7 @@ tracker_db_interface_sqlite_wal_checkpoint (TrackerDBInterface  *interface,
 		return FALSE;
 	}
 
+	g_log (G_LOG_DOMAIN, log_level, "Checkpointing complete");
 	return TRUE;
 }
 
@@ -2406,7 +2412,7 @@ tracker_db_interface_sqlite_finalize (GObject *object)
 	close_database (db_interface);
 	g_free (db_interface->fts_properties);
 
-	g_info ("Closed sqlite3 database:'%s'", db_interface->filename);
+	g_debug ("Closed sqlite3 database:'%s'", db_interface->filename);
 
 	g_free (db_interface->filename);
 
diff --git a/src/libtracker-data/tracker-db-manager.c b/src/libtracker-data/tracker-db-manager.c
index 03684bc95..4c03dc152 100644
--- a/src/libtracker-data/tracker-db-manager.c
+++ b/src/libtracker-data/tracker-db-manager.c
@@ -252,12 +252,12 @@ db_set_params (TrackerDBInterface   *iface,
 	tracker_db_interface_execute_query (iface, NULL, "PRAGMA \"%s\".journal_size_limit = 10240000", database);
 
 	if (page_size != TRACKER_DB_PAGE_SIZE_DONT_SET) {
-		g_info ("  Setting page size to %d", page_size);
+		g_debug ("  Setting page size to %d", page_size);
 		tracker_db_interface_execute_query (iface, NULL, "PRAGMA \"%s\".page_size = %d", database, page_size);
 	}
 
 	tracker_db_interface_execute_query (iface, NULL, "PRAGMA \"%s\".cache_size = %d", database, cache_size);
-	g_info ("  Setting cache size to %d", cache_size);
+	g_debug ("  Setting cache size to %d", cache_size);
 }
 
 void
@@ -265,9 +265,8 @@ tracker_db_manager_remove_all (TrackerDBManager *db_manager)
 {
 	gchar *filename;
 
-	g_info ("Removing all database/storage files");
+	g_info ("Removing all files for database %s", db_manager->db.abs_filename);
 
-	g_info ("  Removing database:'%s'", db_manager->db.abs_filename);
 	g_unlink (db_manager->db.abs_filename);
 
 	/* also delete shm and wal helper files */
@@ -499,12 +498,12 @@ db_recreate_all (TrackerDBManager  *db_manager,
 	 * because at the time 'initialized' = FALSE and that
 	 * will cause errors and do nothing.
 	 */
-	g_info ("Cleaning up database files for reindex");
+	g_debug ("Cleaning up database files for reindex");
 
 	tracker_db_manager_remove_all (db_manager);
 
 	/* Now create the databases and close them */
-	g_info ("Creating database files, this may take a few moments...");
+	g_info ("Creating database files for %s...", db_manager->db.abs_filename);
 
 	db_manager->db.iface = tracker_db_manager_create_db_interface (db_manager, FALSE, &internal_error);
 	if (internal_error) {
@@ -611,7 +610,7 @@ tracker_db_manager_new (TrackerDBManagerFlags   flags,
 	need_reindex = FALSE;
 
 	/* Set up locations */
-	g_info ("Setting database locations");
+	g_debug ("Setting database locations");
 
 	db_manager->flags = flags;
 	db_manager->s_cache_size = select_cache_size;
@@ -631,13 +630,13 @@ tracker_db_manager_new (TrackerDBManagerFlags   flags,
 	if ((flags & TRACKER_DB_MANAGER_READONLY) == 0) {
 
 		/* Make sure the directories exist */
-		g_info ("Checking database directories exist");
+		g_debug ("Checking database directories exist");
 
 		g_mkdir_with_parents (db_manager->data_dir, 00755);
 		g_mkdir_with_parents (db_manager->user_data_dir, 00755);
 	}
 
-	g_info ("Checking whether database files exist");
+	g_debug ("Checking whether database files exist");
 
 	/* Check we have the database in place, if it is
 	 * missing, we reindex.
@@ -718,14 +717,14 @@ tracker_db_manager_new (TrackerDBManagerFlags   flags,
 		tracker_db_manager_update_version (db_manager);
 
 		/* Load databases */
-		g_info ("Loading databases files...");
+		g_info ("Loading files for database %s...", db_manager->db.abs_filename);
 
 	} else if ((flags & TRACKER_DB_MANAGER_READONLY) == 0) {
 		/* do not do shutdown check for read-only mode (direct access) */
 		gboolean must_recreate = FALSE;
 
 		/* Load databases */
-		g_info ("Loading databases files...");
+		g_info ("Loading files for database %s...", db_manager->db.abs_filename);
 
 		if (!must_recreate && g_file_test (db_manager->in_use_filename, G_FILE_TEST_EXISTS)) {
 			gsize size = 0;
@@ -1123,8 +1122,6 @@ wal_checkpoint (TrackerDBInterface *iface,
 {
 	GError *error = NULL;
 
-	g_debug ("Checkpointing database...");
-
 	tracker_db_interface_sqlite_wal_checkpoint (iface, blocking,
 	                                            blocking ? &error : NULL);
 
@@ -1134,8 +1131,6 @@ wal_checkpoint (TrackerDBInterface *iface,
 			   error->message);
 		g_error_free (error);
 	}
-
-	g_debug ("Checkpointing complete");
 }
 
 static gpointer