journald: add debug logs around offlining/archiving/rotating/varlink operations

It is not easy to understand what happens to a journal file
even with debug logs enabled. Add more dbg messages around operations
started by users to make it possible to follow the flow of operations.

(cherry picked from commit 8cc1748ddcbccbe442761416f012da4d746afd3a)

diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c
index bebc1e584c590d03570fb5ad39e995be83c5a1e0..9a517b803f256b031f822b3528552771c8eac4c6 100644 (file)
--- a/src/journal/journald-server.c
+++ b/src/journal/journald-server.c
@@ -554,11 +554,14 @@ static int server_do_rotate(
         JournalFileFlags file_flags;
         int r;
 
+        assert(f);
         assert(s);
 
         if (!*f)
                 return -EINVAL;
 
+        log_debug("Rotating journal file %s.", (*f)->path);
+
         file_flags =
                 (s->compress.enabled ? JOURNAL_COMPRESS : 0)|
                 (seal ? JOURNAL_SEAL : 0) |
@@ -2201,6 +2204,8 @@ static int synchronize_second_half(sd_event_source *event_source, void *userdata
          * messages are processed. */
         server_full_sync(s, /* wait = */ true);
 
+        log_debug("Client request to sync journal completed.");
+
         /* Let's get rid of the event source now, by marking it as non-floating again. It then has no ref
          * anymore and is immediately destroyed after we return from this function, i.e. from this event
          * source handler at the end. */
@@ -2266,6 +2271,7 @@ static int vl_method_rotate(sd_varlink *link, sd_json_variant *parameters, sd_va
 
         log_info("Received client request to rotate journal, rotating.");
         server_full_rotate(s);
+        log_debug("Client request to rotate journal completed.");
 
         return sd_varlink_reply(link, NULL);
 }
@@ -2282,6 +2288,7 @@ static int vl_method_flush_to_var(sd_varlink *link, sd_json_variant *parameters,
 
         log_info("Received client request to flush runtime journal.");
         server_full_flush(s);
+        log_debug("Client request to flush runtime journal completed.");
 
         return sd_varlink_reply(link, NULL);
 }
@@ -2298,6 +2305,7 @@ static int vl_method_relinquish_var(sd_varlink *link, sd_json_variant *parameter
 
         log_info("Received client request to relinquish %s access.", s->system_storage.path);
         server_relinquish_var(s);
+        log_debug("Client request to relinquish %s access completed.", s->system_storage.path);
 
         return sd_varlink_reply(link, NULL);
 }

diff --git a/src/libsystemd/sd-journal/journal-file.c b/src/libsystemd/sd-journal/journal-file.c
index 7e941edb1997136791e188dbb13c5c4e04675cde..7f16183f7c0fa2e08f2fa604e81c7f013a36ff56 100644 (file)
--- a/src/libsystemd/sd-journal/journal-file.c
+++ b/src/libsystemd/sd-journal/journal-file.c
@@ -188,10 +188,14 @@ int journal_file_set_offline_thread_join(JournalFile *f) {
         if (f->offline_state == OFFLINE_JOINED)
                 return 0;
 
+        log_debug("Joining journal offlining thread for %s.", f->path);
+
         r = pthread_join(f->offline_thread, NULL);
         if (r)
                 return -r;
 
+        log_debug("Journal offlining thread for %s joined.", f->path);
+
         f->offline_state = OFFLINE_JOINED;
 
         if (mmap_cache_fd_got_sigbus(f->cache_fd))

diff --git a/src/shared/journal-file-util.c b/src/shared/journal-file-util.c
index 8df165d2f144f9db833768b2bf68c71b137e3f46..55dfc0785a30e414bd483c88eb14dcb7418b963a 100644 (file)
--- a/src/shared/journal-file-util.c
+++ b/src/shared/journal-file-util.c
@@ -10,6 +10,8 @@
 #include "format-util.h"
 #include "journal-authenticate.h"
 #include "journal-file-util.h"
+#include "journal-internal.h"
+#include "log.h"
 #include "path-util.h"
 #include "random-util.h"
 #include "set.h"
@@ -318,12 +320,25 @@ int journal_file_set_offline(JournalFile *f, bool wait) {
 
         target_state = f->archive ? STATE_ARCHIVED : STATE_OFFLINE;
 
+        log_ratelimit_full(LOG_DEBUG,
+                           JOURNAL_LOG_RATELIMIT,
+                           "Journal file %s is %s transitioning to %s.",
+                           f->path,
+                           wait ? "synchronously" : "asynchronously",
+                           f->archive ? "archived" : "offline");
+
         /* An offlining journal is implicitly online and may modify f->header->state,
          * we must also join any potentially lingering offline thread when already in
          * the desired offline state.
          */
-        if (!journal_file_is_offlining(f) && f->header->state == target_state)
+        if (!journal_file_is_offlining(f) && f->header->state == target_state) {
+                log_ratelimit_full(LOG_DEBUG,
+                                   JOURNAL_LOG_RATELIMIT,
+                                   "Journal file %s is already %s, waiting for offlining thread.",
+                                   f->path,
+                                   f->archive ? "archived" : "offline");
                 return journal_file_set_offline_thread_join(f);
+        }
 
         /* Restart an in-flight offline thread and wait if needed, or join a lingering done one. */
         restarted = journal_file_set_offline_try_restart(f);
@@ -336,6 +351,12 @@ int journal_file_set_offline(JournalFile *f, bool wait) {
         if (restarted)
                 return 0;
 
+        log_ratelimit_full(LOG_DEBUG,
+                           JOURNAL_LOG_RATELIMIT,
+                           "Starting new %s offlining operation for journal file %s.",
+                           wait ? "synchronous" : "asynchronous",
+                           f->path);
+
         /* Initiate a new offline. */
         f->offline_state = OFFLINE_SYNCING;