[geary/mjog/579-logging-deadlock: 5/5] Fix deadlock when finalising log records generates more logging

[Michael Gratton <mjog src gnome org>]

commit b43ff7979f16f4c45350cfb0335a635081945bb4
Author: Michael Gratton <mike vee net>
Date:   Sat Sep 28 22:25:36 2019 +1000

    Fix deadlock when finalising log records generates more logging
    
    Make sure records are finalised outside the record lock, and minimise
    the amount of work that happens inside the record lock in general, so
    that no extra logging occurs while in inside it, leading to a deadlock.
    
    Fixes #579

 src/engine/api/geary-logging.vala | 62 ++++++++++++++++++++++++++++-----------
 1 file changed, 45 insertions(+), 17 deletions(-)
---
diff --git a/src/engine/api/geary-logging.vala b/src/engine/api/geary-logging.vala
index faee162b..a509bade 100644
--- a/src/engine/api/geary-logging.vala
+++ b/src/engine/api/geary-logging.vala
@@ -334,9 +334,10 @@ public delegate void LogRecord(Record record);
 
 private int init_count = 0;
 private Flag logging_flags = Flag.NONE;
-private unowned FileStream? stream = null;
 
-// Can't be nullable. See https://gitlab.gnome.org/GNOME/vala/issues/812
+// The two locks below can't be nullable. See
+// https://gitlab.gnome.org/GNOME/vala/issues/812
+
 private GLib.Mutex record_lock;
 private Record? first_record = null;
 private Record? last_record = null;
@@ -344,6 +345,9 @@ private uint log_length = 0;
 private uint max_log_length = 0;
 private unowned LogRecord? listener = null;
 
+private GLib.Mutex writer_lock;
+private unowned FileStream? stream = null;
+
 
 /**
  * Must be called before ''any'' call to the Logging namespace.
@@ -356,6 +360,7 @@ public void init() {
     if (init_count++ != 0)
         return;
     record_lock = GLib.Mutex();
+    writer_lock = GLib.Mutex();
     max_log_length = DEFAULT_MAX_LOG_BUFFER_LENGTH;
 }
 
@@ -369,11 +374,25 @@ public void init() {
 public void clear() {
     record_lock.lock();
 
+    // Keep the old first record around for two reasons. First, so we
+    // don't cause potentially thousands of record to be finalised
+    // under the lock. Second, so finalising doesn't cause an
+    // extremely deep stack as the first record is finalised, causing
+    // the second to be finalised, causing the third..., and so on.
+    Record? old_first = first_record;
+
     first_record = null;
     last_record = null;
     log_length = 0;
-    
+
     record_lock.unlock();
+
+    while (old_first != null) {
+        // Per the second reason above, by manually clearing each log
+        // record here in a loop, finalisation of each is an iterative
+        // process, not recursive.
+        old_first = old_first.next;
+    }
 }
 
 /**
@@ -490,12 +509,13 @@ public void log_to(FileStream? stream) {
 
 public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags levels,
                                                GLib.LogField[] fields) {
-    // Obtain a lock since multiple threads can be calling this
-    // function at the same time
-    record_lock.lock();
-
-    // Update the record linked list
     Record record = new Record(fields, levels, GLib.get_real_time());
+    Record? old_record = null;
+
+    // Update the record linked list. Obtain a lock since multiple
+    // threads could be calling this function at the same time.
+    record_lock.lock();
+    old_record = first_record;
     if (first_record == null) {
         first_record = record;
         last_record = record;
@@ -503,15 +523,20 @@ public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags levels,
         last_record.next = record;
         last_record = record;
     }
-    log_length++;
-    while (log_length > max_log_length) {
+    // Drop the first if we are already at maximum length
+    if (log_length == max_log_length) {
         first_record = first_record.next;
-        log_length--;
-    }
-    if (first_record == null) {
-        last_record = null;
+    } else {
+        log_length++;
     }
+    record_lock.unlock();
+
+    // Now that we are out of the lock, it is safe to finalise any old
+    // records.
+    old_record = null;
 
+    // Ensure the listener is updated on the main loop only, since
+    // this could be getting called from other threads.
     if (listener != null) {
         GLib.MainContext.default().invoke(() => {
                 listener(record);
@@ -519,7 +544,8 @@ public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags levels,
             });
     }
 
-    // Print a log message to the stream
+    // Print a log message to the stream if configured, or if the
+    // priority is high enough.
     unowned FileStream? out = stream;
     if (out != null ||
         LogLevelFlags.LEVEL_WARNING in levels ||
@@ -530,12 +556,14 @@ public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags levels,
             out = GLib.stderr;
         }
 
+        // Lock the writer here so two different threads don't
+        // interleave their lines.
+        writer_lock.lock();
         out.puts(record.format());
         out.putc('\n');
+        writer_lock.unlock();
     }
 
-    record_lock.unlock();
-
     return GLib.LogWriterOutput.HANDLED;
 }