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.

diff --git a/src/journal/journald-manager.c b/src/journal/journald-manager.c
index f984c4a7cc005be9ec2280b525f5f72febc06fea..54dd1f623e3b40cc3c66e62fc7e1cb6fec0bef37 100644 (file)
--- a/src/journal/journald-manager.c
+++ b/src/journal/journald-manager.c
@@ -553,11 +553,14 @@ static int manager_do_rotate(
 
         int r;
 
+        assert(f);
         assert(m);
 
         if (!*f)
                 return -EINVAL;
 
+        log_debug("Rotating journal file %s.", (*f)->path);
+
         r = journal_file_rotate(f, m->mmap, manager_get_file_flags(m, seal), m->config.compress.threshold_bytes, m->deferred_closes);
         if (r < 0) {
                 if (*f)

diff --git a/src/journal/journald-varlink.c b/src/journal/journald-varlink.c
index 81682ea855314450e110f76ab7973391c42892f2..720c3628f1a25abc52fba2e3c10788cb53eae35d 100644 (file)
--- a/src/journal/journald-varlink.c
+++ b/src/journal/journald-varlink.c
@@ -22,6 +22,8 @@ void sync_req_varlink_reply(SyncReq *req) {
         if (req->offline)
                 manager_full_sync(req->manager, /* wait = */ true);
 
+        log_debug("Client request to sync journal (%s offlining) completed.", req->offline ? "with" : "without");
+
         /* Disconnect the SyncReq from the Varlink connection object, and free it */
         _cleanup_(sd_varlink_unrefp) sd_varlink *vl = TAKE_PTR(req->link);
         sd_varlink_set_userdata(vl, req->manager); /* reinstall manager object */
@@ -96,6 +98,7 @@ static int vl_method_rotate(sd_varlink *link, sd_json_variant *parameters, sd_va
 
         log_info("Received client request to rotate journal, rotating.");
         manager_full_rotate(m);
+        log_debug("Client request to rotate journal completed.");
 
         return sd_varlink_reply(link, NULL);
 }
@@ -119,6 +122,7 @@ static int vl_method_flush_to_var(sd_varlink *link, sd_json_variant *parameters,
 
         log_info("Received client request to flush runtime journal.");
         manager_full_flush(m);
+        log_debug("Client request to flush runtime journal completed.");
 
         return sd_varlink_reply(link, NULL);
 }
@@ -142,6 +146,7 @@ static int vl_method_relinquish_var(sd_varlink *link, sd_json_variant *parameter
 
         log_info("Received client request to relinquish %s access.", m->system_storage.path);
         manager_relinquish_var(m);
+        log_debug("Client request to relinquish %s access completed.", m->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 2a08f923d1191ac2d9749a52efcf0d94d34e6db7..c6ddac95986e87459780bc97c325d5b9284deb82 100644 (file)
--- a/src/libsystemd/sd-journal/journal-file.c
+++ b/src/libsystemd/sd-journal/journal-file.c
@@ -197,10 +197,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 990146b62465e4e342500d2fae08bb09d7d1109d..6591744c51249a9bad1087dc7b342622d502b677 100644 (file)
--- a/src/shared/journal-file-util.c
+++ b/src/shared/journal-file-util.c
@@ -12,7 +12,9 @@
 #include "fd-util.h"
 #include "journal-authenticate.h"
 #include "journal-file-util.h"
+#include "journal-internal.h"
 #include "log.h"
+#include "log-ratelimit.h"
 #include "set.h"
 #include "string-util.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;