[tracker/sam/tracker-2.3-developer-experience: 29/38] Reduce the amount of log messages with TRACKER_VERBOSITY=1

[Sam Thursfield <sthursfield src gnome org>]

commit 1fd180aeaa5c2d6c45d037bf28ae3a3b050ec1b0
Author: Sam Thursfield <sam afuera me uk>
Date:   Sun Sep 22 19:16:08 2019 +0200

    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).

 src/libtracker-data/tracker-db-interface-sqlite.c | 10 +++++++--
 src/libtracker-data/tracker-db-manager.c          | 25 +++++++++--------------
 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 16d201d10..af211f085 100644
--- a/src/libtracker-data/tracker-db-interface-sqlite.c
+++ b/src/libtracker-data/tracker-db-interface-sqlite.c
@@ -1528,7 +1528,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 */
@@ -1962,6 +1962,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,
@@ -1975,6 +1980,7 @@ tracker_db_interface_sqlite_wal_checkpoint (TrackerDBInterface  *interface,
                return FALSE;
        }
 
+       g_log (G_LOG_DOMAIN, log_level, "Checkpointing complete");
        return TRUE;
 }
 
@@ -1988,7 +1994,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 556bea39d..35ea1bae2 100644
--- a/src/libtracker-data/tracker-db-manager.c
+++ b/src/libtracker-data/tracker-db-manager.c
@@ -243,12 +243,12 @@ db_set_params (TrackerDBInterface   *iface,
        tracker_db_interface_execute_query (iface, NULL, "PRAGMA journal_size_limit = 10240000");
 
        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 page_size = %d", page_size);
        }
 
        tracker_db_interface_execute_query (iface, NULL, "PRAGMA cache_size = %d", cache_size);
-       g_info ("  Setting cache size to %d", cache_size);
+       g_debug ("  Setting cache size to %d", cache_size);
 }
 
 void
@@ -256,9 +256,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 */
@@ -497,12 +496,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) {
@@ -616,7 +615,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;
@@ -636,7 +635,7 @@ 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);
@@ -655,7 +654,7 @@ tracker_db_manager_new (TrackerDBManagerFlags   flags,
                }
        }
 
-       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.
@@ -725,14 +724,14 @@ tracker_db_manager_new (TrackerDBManagerFlags   flags,
                }
 
                /* 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);
 
 #ifndef DISABLE_JOURNAL
                must_recreate = !tracker_db_journal_reader_verify_last (data_location,
@@ -1109,8 +1108,6 @@ wal_checkpoint (TrackerDBInterface *iface,
 {
        GError *error = NULL;
 
-       g_debug ("Checkpointing database...");
-
        tracker_db_interface_sqlite_wal_checkpoint (iface, blocking,
                                                    blocking ? &error : NULL);
 
@@ -1120,8 +1117,6 @@ wal_checkpoint (TrackerDBInterface *iface,
                           error->message);
                g_error_free (error);
        }
-
-       g_debug ("Checkpointing complete");
 }
 
 static gpointer