Support rotating log buffers

doc/manpages/dinit-service.5.m4

@@ -469,7 +469,8 @@ This setting is valid only for process-based services (including \fBscripted\fR
 .IP \(bu
 \fBfile\fR: output will be written to a file; see the \fBlogfile\fR setting.
 .IP \(bu
-\fBbuffer\fR: output will be buffered in memory, up to a limit specified via the
+\fBbuffer\fR: output will be buffered in memory, and automatically rotated when reaching the limit
+specified via the
 \fBlog\-buffer\-size\fR setting.
 The buffer contents can be examined via the \fBdinitctl\fR(8) \fBcatlog\fR subcommand. 
 .IP \(bu
@@ -524,7 +525,8 @@ Specifies the group of the log file. See discussion of \fBlogfile\-uid\fR.
 \fBlog\-buffer\-size\fR = \fIsize-in-bytes\fR
 If the log type (see \fBlog\-type\fR) is set to \fBbuffer\fR, this setting controls the maximum
 size of the buffer used to store process output.
-If the buffer becomes full, further output from the service process will be discarded.
+The output from the service will be rotated, i.e. FIFO, if the buffer becomes full.
+Only positive integers are allowed for this setting.
 .TP
 \fBconsumer\-of\fR = \fIservice-name\fR
 Specifies that this service consumes (as its standard input) the output of another service.

src/baseproc-service.cc

@@ -200,28 +200,17 @@ bool base_process_service::start_ps_process(const std::vector<const char *> &cmd
         }
 
         if (log_type == log_type_id::BUFFER) {
-            // Set watcher enabled if space in buffer
-            if (log_buf_size > 0) {
-                // Append a "restarted" message to buffer contents
+            if (log_buf_size) {
                 const char *restarting_msg = "\n(dinit: note: service restarted)\n";
-                unsigned restarting_msg_len = strlen(restarting_msg);
-                bool trailing_nl = log_buffer[log_buf_size - 1] == '\n';
-                if (trailing_nl) {
-                    ++restarting_msg; // trim leading newline
-                    --restarting_msg_len;
-                }
-                if (log_buf_size + restarting_msg_len >= log_buf_max) {
-                    goto skip_enable_log_watch;
-                }
-                if (!ensure_log_buffer_backing(log_buf_size + restarting_msg_len)) {
-                    goto skip_enable_log_watch;
-                }
-                memcpy(log_buffer.data() + log_buf_size, restarting_msg, restarting_msg_len);
-                log_buf_size += restarting_msg_len;
+
+                // Trim the leading newline if it leads to empty lines
+                if (log_buffer_peek(-1) == '\n')
+                    restarting_msg++;
+
+                log_buffer_append(restarting_msg, strlen(restarting_msg));
             }
             log_output_listener.set_enabled(event_loop, true);
         }
-        skip_enable_log_watch: ;
 
         // Set up complete, now fork and exec:
 
@@ -614,5 +603,51 @@ bool base_process_service::ensure_log_buffer_backing(unsigned new_size) noexcept
             log_buffer.resize(new_size);
         }
     }
+    log_buf_size = new_size;
+    return true;
+}
+
+bool base_process_service::log_buffer_append(const char *log, unsigned size) noexcept
+{
+    if (!ensure_log_buffer_backing(std::min((unsigned)log_buf_size + size, log_buf_max))) {
+        return false;
+    }
+
+    if (size > log_buf_max) {
+        log += size - log_buf_max;
+        size = log_buf_max;
+    }
+
+    if (log_buf_pointer + size > log_buf_max) {
+        unsigned int slice1 = log_buf_max - log_buf_pointer;
+        unsigned int slice2 = size - slice1;
+        memcpy(log_buffer.data() + log_buf_pointer, log, slice1);
+        memcpy(log_buffer.data(), log + slice1, slice2);
+    }
+    else {
+        memcpy(log_buffer.data() + log_buf_pointer, log, size);
+    }
+
+    log_buf_pointer = (log_buf_pointer + size) % log_buf_max;
+
     return true;
 }
+
+static void reverse_in_place(char *s, unsigned int len)
+{
+    for (unsigned i = 0; i < len / 2; i++)
+        std::swap(s[i], s[len - i - 1]);
+}
+
+void base_process_service::linearize_log_buffer() noexcept
+{
+    if (log_buf_size < log_buf_max) {
+        return;
+    }
+
+    reverse_in_place(log_buffer.data(), log_buf_pointer);
+    reverse_in_place(log_buffer.data() + log_buf_pointer, log_buf_max - log_buf_pointer);
+    reverse_in_place(log_buffer.data(), log_buf_max);
+
+    log_buf_pointer = 0;
+}

src/igr-tests/catlog/output-long.sh

@@ -0,0 +1,5 @@
+#!/bin/sh
+
+echo "123456789"
+echo "abcdefghi"
+echo "deadbeaf"

src/igr-tests/catlog/sd/boot → src/igr-tests/catlog/sd1/boot

@@ -1,2 +1,3 @@
 type = internal
 waits-for = output
+waits-for = output-long

src/igr-tests/catlog/sd1/output-long

@@ -0,0 +1,5 @@
+type = scripted
+command = ../output-long.sh
+restart = false
+log-type = buffer
+log-buffer-size = 16

src/igr-tests/catlog/sd2/boot

@@ -0,0 +1,3 @@
+type = internal
+waits-for = output
+waits-for = output-long

src/igr-tests/catlog/sd2/output

@@ -0,0 +1,4 @@
+type = scripted
+command = ../output.sh
+restart = false
+log-type = buffer

src/igr-tests/catlog/sd2/output-long

@@ -0,0 +1,5 @@
+type = scripted
+command = ../output-long.sh
+restart = false
+log-type = buffer
+log-buffer-size = 4096

src/igr-tests/igr-runner.cc

@@ -907,36 +907,99 @@ void catlog_test()
     igr_test_setup setup("catlog");
     std::string socket_path = setup.prep_socket_path();
 
+    std::string sd_dir = setup.get_output_dir() + "/sd";
+    auto replace_sd_dir = [&](std::string dir) {
+        unlink(sd_dir.c_str());
+        if (symlink((igr_input_basedir + dir).c_str(), sd_dir.c_str()) == -1) {
+            throw std::system_error(errno, std::generic_category(), "symlink");
+        }
+    };
+
+    replace_sd_dir("/catlog/sd1");
+
     dinit_proc dinit_p;
-    dinit_p.start("catlog", {"-u", "-d", "sd", "-p", socket_path, "-q"}, true);
+    dinit_p.start("catlog", {"-u", "-d", sd_dir, "-p", socket_path, "-q"}, true);
 
-    // wait until "output" has actually started
     dinitctl_proc dinitctl_p;
-    dinitctl_p.start("catlog", {"-u", "-p", socket_path, "start", "output"});
-    int status = dinitctl_p.wait_for_term({1, 0}); /* max 1 second */
-    igr_assert(status == 0, "dinitctl did not exit cleanly");
+    auto dinitctl_run = [&](std::vector<std::string> extraArgs) {
+        std::vector<std::string> args = {"-u", "-p", socket_path};
+        args.insert(args.end(), extraArgs.begin(), extraArgs.end());
 
-    dinitctl_p.start("catlog", {"-u", "-p", socket_path, "catlog", "output"});
-    status = dinitctl_p.wait_for_term({1, 0}); /* max 1 second */
-    igr_assert(status == 0, "dinitctl did not exit cleanly");
+        dinitctl_p.start("catlog", args);
+        int status = dinitctl_p.wait_for_term({1, 0}); /* max 1 second */
+        igr_assert(status == 0, "dinitctl did not exit cleanly");
+    };
 
+    // wait until "output" has actually started
+
+    dinitctl_run({"start", "output"});
+    dinitctl_run({"catlog", "output"});
     igr_assert_eq("Output...\n", dinitctl_p.get_stdout());
 
-    // Check output again, this time also clear the buffer
+    // Check for the restarting message
 
-    dinitctl_p.start("catlog", {"-u", "-p", socket_path, "catlog", "--clear", "output"});
-    status = dinitctl_p.wait_for_term({1, 0}); /* max 1 second */
-    igr_assert(status == 0, "dinitctl did not exit cleanly");
+    dinitctl_run({"restart", "output"});
+    dinitctl_run({"catlog", "output"});
+    igr_assert_eq("Output...\n(dinit: note: service restarted)\nOutput...\n",
+                  dinitctl_p.get_stdout());
 
-    igr_assert_eq("Output...\n", dinitctl_p.get_stdout());
+    // Check output again, this time also clear the buffer
+
+    dinitctl_run({"catlog", "--clear", "output"});
+    igr_assert_eq("Output...\n(dinit: note: service restarted)\nOutput...\n",
+                  dinitctl_p.get_stdout());
 
     // Check a third time, buffer should be clear now
 
-    dinitctl_p.start("catlog", {"-u", "-p", socket_path, "catlog", "--clear", "output"});
-    status = dinitctl_p.wait_for_term({1, 0}); /* max 1 second */
-    igr_assert(status == 0, "dinitctl did not exit cleanly");
+    dinitctl_run({"catlog", "--clear", "output"});
 
     igr_assert_eq("", dinitctl_p.get_stdout());
+
+    // Restart a service with empty log buffer should yield no restarting message
+    dinitctl_run({"restart", "output"});
+    dinitctl_run({"catlog", "output"});
+    igr_assert_eq("Output...\n", dinitctl_p.get_stdout());
+
+    // wait until "output-long" has actually started
+    dinitctl_run({"start", "output-long"});
+
+    // Check whether log buffer is correctly rotated
+
+    dinitctl_run({"catlog", "output-long"});
+
+    igr_assert_eq("defghi\ndeadbeaf\n", dinitctl_p.get_stdout());
+
+    // Restart the service, which will cause a message longer than the buffer
+    // being buffered
+
+    dinitctl_run({"restart", "output-long"});
+    dinitctl_run({"catlog", "output-long"});
+    igr_assert_eq("defghi\ndeadbeaf\n", dinitctl_p.get_stdout());
+
+    replace_sd_dir("/catlog/sd2");
+
+    // Reload output-long, increasing its log buffer's size
+
+    dinitctl_run({"reload", "output-long"});
+    dinitctl_run({"catlog", "output-long"});
+    igr_assert_eq("defghi\ndeadbeaf\n", dinitctl_p.get_stdout());
+
+    // Restart the service, then roll back to the smaller buffer size, see whether the log is
+    // correctly truncated
+
+    dinitctl_run({"restart", "output-long"});
+    dinitctl_run({"catlog", "output-long"});
+    igr_assert_eq("defghi\ndeadbeaf\n(dinit: note: service restarted)\n123456789\nabcdefghi\ndeadbeaf\n",
+                  dinitctl_p.get_stdout());
+
+    replace_sd_dir("/catlog/sd1");
+
+    dinitctl_run({"reload", "output-long"});
+    dinitctl_run({"catlog", "output-long"});
+
+    igr_assert_eq("defghi\ndeadbeaf\n", dinitctl_p.get_stdout());
+
+    unlink(sd_dir.c_str());
 }
 
 void offline_enable_test()

src/includes/load-service.h

@@ -2284,6 +2284,11 @@ void process_service_line(settings_wrapper &settings, ::string_view name, const
             string log_buffer_size_str = read_setting_value(input_pos, i, end);
             unsigned bufsize = (unsigned)parse_unum_param(input_pos, log_buffer_size_str, name,
                     std::numeric_limits<unsigned>::max() / 2);
+
+            if (!bufsize)
+                throw service_description_exc(name, "log-buffer-size cannot be zero",
+                                              details->setting_str, input_pos);
+
             settings.max_log_buffer_sz = bufsize;
             break;
         }

src/includes/proc-service.h

@@ -1,3 +1,5 @@
+#include <algorithm>
+#include <cstring>
 #include <vector>
 #include <string>
 #include <list>
@@ -202,6 +204,7 @@ class base_process_service : public service_record
     gid_t logfile_gid = -1;  // logfile group id
     unsigned log_buf_max = 0; // log buffer maximum size
     unsigned log_buf_size = 0; // log buffer current size
+    unsigned log_buf_pointer = 0; // log buffer write pointer
     std::vector<char, default_init_allocator<char>> log_buffer;
 
     bool nice_is_set = false;
@@ -346,7 +349,17 @@ class base_process_service : public service_record
         return nullptr;
     }
 
+    bool log_buffer_append(const char *log, unsigned size) noexcept;
+    // Peek the buffer, negative index counts backwards
+    char log_buffer_peek(int index) noexcept
+    {
+        return log_buffer.data()[(log_buf_pointer + index + log_buf_max) % log_buf_max];
+    }
+
+    private:
     bool ensure_log_buffer_backing(unsigned size) noexcept;
+    // Linearize the circular buffer to be used externally
+    void linearize_log_buffer() noexcept;
 
     public:
     // Constructor for a base_process_service. Note that the various parameters not specified here must in
@@ -403,6 +416,28 @@ class base_process_service : public service_record
     // (must be checked by caller).
     void set_log_buf_max(unsigned max_size) noexcept
     {
+        if (log_buf_max == max_size) {
+            return;
+        }
+
+        linearize_log_buffer();
+
+        if (log_buf_max < max_size) {
+            // Growing the buffer, move the writing pointer past the end of the current buffer.
+            log_buf_pointer = log_buf_size;
+        }
+        else if (log_buf_size >= max_size) {
+            // The buffer will become full
+            log_buf_pointer = 0;
+
+            if (log_buf_size > max_size) {
+                // Shrinking the buffer, and the content must be truncated to fit.
+                // Move the content forward.
+                memmove(log_buffer.data(), log_buffer.data() + log_buf_size - max_size, max_size);
+                log_buf_size = max_size;
+            }
+        }
+
         this->log_buf_max = max_size;
     }
 
@@ -468,14 +503,16 @@ class base_process_service : public service_record
     // Get the log buffer (address, length)
     std::pair<const char *, unsigned> get_log_buffer() noexcept
     {
-        return {log_buffer.data(), log_buf_size};
+        linearize_log_buffer();
+        return {log_buffer.data(), std::min(log_buf_size, log_buf_max)};
     }
 
     void clear_log_buffer() noexcept
     {
         log_buffer.clear();
         log_buffer.shrink_to_fit();
         log_buf_size = 0;
+        log_buf_pointer = 0;
     }
 
     void set_env_file(const std::string &env_file_p)