From 8f65507d950a15df84ee33aee2630d8b8ed1f1b3 Mon Sep 17 00:00:00 2001
From: Ryan Gonzalez <ryan.gonzalez@collabora.com>
Date: Fri, 2 Aug 2024 15:52:38 -0500
Subject: [PATCH] logger: Recreate output log files if they get deleted

Before writing a log line to the file, first check to make sure that
it's still around. If not, then just re-create it, so that clearing the
current logs out doesn't actually stop future logs from appearing.

This takes advantage of the existing fstat() setup that checks the file
size and swaps it out with stat() to be able to pick up on the file
going missing. (That change shouldn't introduce any notable race
conditions on the directory side, because srt-logger has already chdir'd
into the log file directly, and self->filename isn't a full path in the
first place.)

steamrt/tasks#487

Signed-off-by: Ryan Gonzalez <ryan.gonzalez@collabora.com>
---
 steam-runtime-tools/logger.c | 67 ++++++++++++++++++++++++++++++------
 tests/test-logger.py         | 39 +++++++++++++++++++++
 2 files changed, 95 insertions(+), 11 deletions(-)

diff --git a/steam-runtime-tools/logger.c b/steam-runtime-tools/logger.c
index 130bf4396..d5b6a6bb8 100644
--- a/steam-runtime-tools/logger.c
+++ b/steam-runtime-tools/logger.c
@@ -86,6 +86,7 @@ struct _SrtLogger {
   gchar *new_filename;
   gchar *log_dir;
   gchar *terminal;
+  struct stat file_stat;
   int child_ready_to_parent;
   int pipe_from_parent;
   int original_stderr;
@@ -475,6 +476,11 @@ _srt_logger_setup (SrtLogger *self,
                                         "Unable to open \"%s\"",
                                         self->filename);
 
+      if (fstat (self->file_fd, &self->file_stat) < 0)
+        return glnx_throw_errno_prefix (error,
+                                        "Unable to stat \"%s\"",
+                                        self->filename);
+
       message = g_string_new (g_get_prgname ());
       date_time = g_date_time_new_now_local ();
       timestamp = g_date_time_format (date_time, "%F %T%z");
@@ -1020,6 +1026,7 @@ _srt_logger_try_rotate (SrtLogger *self,
   struct flock exclusive_lock = EXCLUSIVE_LOCK;
   struct flock shared_lock = SHARED_LOCK;
   glnx_autofd int new_fd = -1;
+  struct stat new_stat;
   gboolean ret = FALSE;
 
   g_debug ("Trying to rotate log file %s", self->filename);
@@ -1069,6 +1076,14 @@ _srt_logger_try_rotate (SrtLogger *self,
       goto out;
     }
 
+  if (fstat (new_fd, &new_stat) < 0)
+    {
+      glnx_throw_errno_prefix (error,
+                               "Unable to stat \"%s\"",
+                               self->new_filename);
+      goto out;
+    }
+
   if (TEMP_FAILURE_RETRY (rename (self->new_filename, self->filename)) != 0)
     {
       glnx_throw_errno_prefix (error, "Unable to rename %s to %s",
@@ -1078,6 +1093,7 @@ _srt_logger_try_rotate (SrtLogger *self,
 
   glnx_close_fd (&self->file_fd);
   self->file_fd = g_steal_fd (&new_fd);
+  memcpy (&self->file_stat, &new_stat, sizeof (new_stat));
   ret = TRUE;
 
 out:
@@ -1198,20 +1214,49 @@ logger_process_complete_line (SrtLogger *self,
 
   if (self->file_fd >= 0 && level <= self->file_level)
     {
-      struct stat stat_buf;
-
-      if (self->max_bytes > 0
-          && self->filename != NULL
-          && fstat (self->file_fd, &stat_buf) == 0
-          && (stat_buf.st_size + len) > self->max_bytes)
+      if (self->filename != NULL)
         {
-          g_autoptr(GError) local_error = NULL;
+          gboolean log_file_still_exists = FALSE;
+          struct stat current_stat;
+
+          if (TEMP_FAILURE_RETRY (stat (self->filename, &current_stat)) == 0)
+            log_file_still_exists = _srt_is_same_stat (&current_stat,
+                                                       &self->file_stat);
+          else if (errno != ENOENT)
+            _srt_log_warning ("Unable to stat log file: %s",
+                              g_strerror (errno));
 
-          if (!_srt_logger_try_rotate (self, &local_error))
+          if (!log_file_still_exists)
+            {
+              /* The log file is either deleted or replaced, probably by a
+               * developer who wanted to clear the logs out. Re-create it now
+               * instead of staying silent. */
+              glnx_autofd int new_fd = -1;
+              g_autoptr(GError) local_error = NULL;
+
+              new_fd = TEMP_FAILURE_RETRY (open (self->filename,
+                                                 OPEN_FLAGS,
+                                                 0644));
+              if (new_fd < 0)
+                _srt_log_warning ("Unable to re-open log file: %s",
+                                  g_strerror (errno));
+              else if (!lock_output_file (self->filename, new_fd, &local_error))
+                _srt_log_warning ("Unable to re-lock log file: %s",
+                                  local_error->message);
+              else
+                self->file_fd = glnx_steal_fd (&new_fd);
+            }
+          else if (self->max_bytes > 0
+                   && (current_stat.st_size + len) > self->max_bytes)
             {
-              _srt_log_warning ("Unable to rotate log file: %s",
-                                local_error->message);
-              self->max_bytes = 0;
+              g_autoptr(GError) local_error = NULL;
+
+              if (!_srt_logger_try_rotate (self, &local_error))
+                {
+                  _srt_log_warning ("Unable to rotate log file: %s",
+                                    local_error->message);
+                  self->max_bytes = 0;
+                }
             }
         }
 
diff --git a/tests/test-logger.py b/tests/test-logger.py
index 2fd8f694e..ff315f9b3 100755
--- a/tests/test-logger.py
+++ b/tests/test-logger.py
@@ -677,6 +677,45 @@ class TestLogger(BaseTest):
                 content = reader.read()
                 self.assertIn(b'last message\n', content)
 
+    def test_reopen(self) -> None:
+        for replaced in False, True:
+            with tempfile.TemporaryDirectory() as tmpdir:
+                log_path = Path(tmpdir) / 'log'
+
+                proc = subprocess.Popen(
+                    self.logger + [
+                        '--filename', log_path.name,
+                        '--log-directory', str(log_path.parent),
+                        '--no-auto-terminal',
+                    ],
+                    stdin=subprocess.PIPE,
+                    stdout=STDERR_FILENO,
+                    stderr=STDERR_FILENO,
+                )
+
+                with wrap_process_io(proc.stdin) as stdin:
+                    stdin.write('first message\n')
+                    stdin.flush()
+
+                    while (not log_path.exists()
+                            or 'first message' not in log_path.read_text()):
+                        time.sleep(0.1)
+
+                    if replaced:
+                        tmp_path = log_path.with_suffix('.tmp')
+                        tmp_path.touch()
+                        tmp_path.rename(log_path)
+                    else:
+                        log_path.unlink()
+
+                    stdin.write('second message\n')
+                    stdin.flush()
+
+                proc.wait()
+
+                content = log_path.read_text()
+                self.assertIn('second message', content)
+
     def test_stderr_only(self) -> None:
         proc = subprocess.Popen(
             self.logger + [
-- 
GitLab