diff --git a/doc/manpages/dinit-service.5.m4 b/doc/manpages/dinit-service.5.m4 index f26e9cfd..936ed0fc 100644 --- a/doc/manpages/dinit-service.5.m4 +++ b/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. diff --git a/src/baseproc-service.cc b/src/baseproc-service.cc index be9ca7d4..d634c468 100644 --- a/src/baseproc-service.cc +++ b/src/baseproc-service.cc @@ -200,28 +200,17 @@ bool base_process_service::start_ps_process(const std::vector &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; +} diff --git a/src/igr-tests/catlog/output-long.sh b/src/igr-tests/catlog/output-long.sh new file mode 100755 index 00000000..c2db8a32 --- /dev/null +++ b/src/igr-tests/catlog/output-long.sh @@ -0,0 +1,5 @@ +#!/bin/sh + +echo "123456789" +echo "abcdefghi" +echo "deadbeaf" diff --git a/src/igr-tests/catlog/sd/boot b/src/igr-tests/catlog/sd1/boot similarity index 59% rename from src/igr-tests/catlog/sd/boot rename to src/igr-tests/catlog/sd1/boot index ccb7daa3..cf5fb91d 100644 --- a/src/igr-tests/catlog/sd/boot +++ b/src/igr-tests/catlog/sd1/boot @@ -1,2 +1,3 @@ type = internal waits-for = output +waits-for = output-long diff --git a/src/igr-tests/catlog/sd/output b/src/igr-tests/catlog/sd1/output similarity index 100% rename from src/igr-tests/catlog/sd/output rename to src/igr-tests/catlog/sd1/output diff --git a/src/igr-tests/catlog/sd1/output-long b/src/igr-tests/catlog/sd1/output-long new file mode 100644 index 00000000..943575c2 --- /dev/null +++ b/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 diff --git a/src/igr-tests/catlog/sd2/boot b/src/igr-tests/catlog/sd2/boot new file mode 100644 index 00000000..cf5fb91d --- /dev/null +++ b/src/igr-tests/catlog/sd2/boot @@ -0,0 +1,3 @@ +type = internal +waits-for = output +waits-for = output-long diff --git a/src/igr-tests/catlog/sd2/output b/src/igr-tests/catlog/sd2/output new file mode 100644 index 00000000..c561cbb4 --- /dev/null +++ b/src/igr-tests/catlog/sd2/output @@ -0,0 +1,4 @@ +type = scripted +command = ../output.sh +restart = false +log-type = buffer diff --git a/src/igr-tests/catlog/sd2/output-long b/src/igr-tests/catlog/sd2/output-long new file mode 100644 index 00000000..66d6d778 --- /dev/null +++ b/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 diff --git a/src/igr-tests/igr-runner.cc b/src/igr-tests/igr-runner.cc index 6f4e32fa..97317592 100644 --- a/src/igr-tests/igr-runner.cc +++ b/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 extraArgs) { + std::vector 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() diff --git a/src/includes/load-service.h b/src/includes/load-service.h index 2a45c6de..b4e4c898 100644 --- a/src/includes/load-service.h +++ b/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::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; } diff --git a/src/includes/proc-service.h b/src/includes/proc-service.h index e16b2925..70bb6d58 100644 --- a/src/includes/proc-service.h +++ b/src/includes/proc-service.h @@ -1,3 +1,5 @@ +#include +#include #include #include #include @@ -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> 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,7 +503,8 @@ class base_process_service : public service_record // Get the log buffer (address, length) std::pair 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 @@ -476,6 +512,7 @@ class base_process_service : public service_record 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) diff --git a/src/proc-service.cc b/src/proc-service.cc index d9122d69..7513082e 100644 --- a/src/proc-service.cc +++ b/src/proc-service.cc @@ -287,47 +287,24 @@ dasynq::rearm stop_child_watcher::status_change(eventloop_t &loop, pid_t child, rearm log_output_watcher::fd_event(eventloop_t &eloop, int fd, int flags) noexcept { - // In case buffer size has been decreased, check if we are already at the limit: - if (service->log_buf_size >= service->log_buf_max) { - // If so, read and discard. - char buf[1024]; - int r = bp_sys::read(fd, buf, 1024); - if (r == -1) { - if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) { - return rearm::REARM; - } - goto bad_read; - } - if (r == 0) goto eof_read; - return rearm::REARM; - } - - { - size_t max_read = std::max(service->log_buf_max / 8, 256u); - max_read = std::min((unsigned)max_read, service->log_buf_max - service->log_buf_size); - - // ensure vector has size sufficient to read - unsigned new_size = service->log_buf_size + max_read; - if (!service->ensure_log_buffer_backing(new_size)) { - return rearm::DISARM; - } - - max_read = service->log_buffer.size() - service->log_buf_size; + char buf[1024]; - int r = bp_sys::read(fd, service->log_buffer.data() + service->log_buf_size, max_read); - if (r == -1) { - if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) { - return rearm::REARM; - } - goto bad_read; + int r = bp_sys::read(fd, buf, sizeof(buf)); + if (r == -1) { + if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) { + return rearm::REARM; } + goto bad_read; + } - if (r == 0) goto eof_read; + if (r == 0) goto eof_read; - service->log_buf_size += r; - return rearm::REARM; + if (!service->log_buffer_append(buf, r)) { + return rearm::DISARM; } + return rearm::REARM; + // error/end-of-stream handling: bad_read: