Introduce log write buffering

Change-Id: Iac626630b6885a4214e42c5f810aa50d98d66ecb

diff --git a/configs/dlog_logger.service.in b/configs/dlog_logger.service.in
index 99e527d..1b94493 100644 (file)
--- a/configs/dlog_logger.service.in
+++ b/configs/dlog_logger.service.in
@@ -20,7 +20,7 @@ Environment=TZ=:/etc/localtime
 User=@DLOG_SERVER_USER@
 Group=@DLOG_SERVER_GROUP@
 SmackProcessLabel=System
-ExecStart=/usr/bin/dlog_logger -b 99 -t 600
+ExecStart=/usr/bin/dlog_logger
 Capabilities=cap_syslog=i
 SecureBits=keep-caps
 Restart=always

diff --git a/include/log_file.h b/include/log_file.h
index 9ffc184..2fc0382 100644 (file)
--- a/include/log_file.h
+++ b/include/log_file.h
@@ -40,6 +40,7 @@ struct log_file {
        struct log_format format;
        bool isatty;
        bool colors_auto;
+       struct log_write_buffer buffer;
        int32_t prev_sec;  /* previously written entry's timestamp, seconds */
        int32_t prev_nsec; /* previously written timestamp, nanoseconds */
 };
@@ -49,6 +50,7 @@ extern "C" {
 #endif
 
 void logfile_init(struct log_file *l_file);
+bool logfile_init_buffer(struct log_file *l_file, size_t buf_size);
 void logfile_move(struct log_file *to, struct log_file *from);
 void logfile_free(struct log_file *l_file);
 void logfile_set_fd(struct log_file *l_file, int fd, int should_close);
@@ -56,6 +58,7 @@ int logfile_set_path(struct log_file *l_file, const char *path);
 int logfile_open(struct log_file *l_file);
 int logfile_rotate_needed(struct log_file *l_file);
 void logfile_do_rotate(struct log_file *file);
+int logfile_flush(struct log_file *file);
 int logfile_write_with_rotation(const dlogutil_entry_s *e, struct log_file *file, dlogutil_sorting_order_e sort_by);
 
 #ifdef __cplusplus

diff --git a/include/logprint.h b/include/logprint.h
index 072f12a..5f58aa3 100644 (file)
--- a/include/logprint.h
+++ b/include/logprint.h
@@ -53,10 +53,20 @@ struct log_format {
        bool color;
 };
 
+struct log_write_buffer {
+       char *data;
+       size_t position;
+       size_t size;
+       struct timespec oldest_log;
+};
 dlogutil_filter_options_s *log_filter_new();
 
 void log_filter_free(dlogutil_filter_options_s *p_filter);
 
+struct log_write_buffer log_write_buffer_new();
+
+void log_write_buffer_free(struct log_write_buffer *buf);
+
 /**
  * Returns a deep copy of the passed object.
  */
@@ -141,7 +151,8 @@ char *log_format_log_line(
 int log_print_log_line(
                struct log_format p_format,
                int fd,
-               const dlogutil_entry_s *entry);
+               const dlogutil_entry_s *entry,
+               struct log_write_buffer *buf);
 
 dlogutil_sorting_order_e get_format_sorting(log_print_format format);
 

diff --git a/src/logger/dlogutil_line.c b/src/logger/dlogutil_line.c
index d8280c2..8f48a24 100644 (file)
--- a/src/logger/dlogutil_line.c
+++ b/src/logger/dlogutil_line.c
@@ -9,11 +9,12 @@ void reset_getopt_internals(void *fake)
        optopt = 0;
 }
 
-bool initialize_dlogutil_line_params(struct dlogutil_line_params *params)
+bool initialize_dlogutil_line_params(struct dlogutil_line_params *params, struct buf_params buf)
 {
        assert(params);
 
-       logfile_init(&params->file);
+       logfile_init(&params->file); // TODO: add flush
+       logfile_init_buffer(&params->file, buf.bytes);
        params->monitor = false;
        params->is_dumping = false;
        params->buf_id = LOG_ID_INVALID;
@@ -161,4 +162,3 @@ int get_dlogutil_line_params(const char *cmdl, struct dlogutil_line_params *para
 
        return get_dlogutil_params_from_argc_argv(argc, argv, params);
 }
-

diff --git a/src/logger/dlogutil_line.h b/src/logger/dlogutil_line.h
index 490bd90..9582904 100644 (file)
--- a/src/logger/dlogutil_line.h
+++ b/src/logger/dlogutil_line.h
@@ -2,6 +2,11 @@
 
 #include <log_file.h>
 
+struct buf_params {
+       int bytes;
+       int time;
+};
+
 struct dlogutil_line_params {
        bool monitor;
        bool is_dumping;
@@ -11,7 +16,7 @@ struct dlogutil_line_params {
        struct dlogutil_filter_options *filter;
 };
 
-bool initialize_dlogutil_line_params(struct dlogutil_line_params *params);
+bool initialize_dlogutil_line_params(struct dlogutil_line_params *params, struct buf_params buf);
 int get_dlogutil_line_params(const char *cmdl, struct dlogutil_line_params *params);
 void free_dlogutil_line_params(struct dlogutil_line_params *params);
 

diff --git a/src/logger/log_buffer.c b/src/logger/log_buffer.c
index dc2c771..7bd3cc8 100644 (file)
--- a/src/logger/log_buffer.c
+++ b/src/logger/log_buffer.c
@@ -95,7 +95,7 @@ static int service_writer_handle_req_util(struct logger* server, struct writer*
 
        int retval;
        __attribute__((cleanup(free_dlogutil_line_params))) struct dlogutil_line_params params;
-       if (!initialize_dlogutil_line_params(&params)) {
+       if (!initialize_dlogutil_line_params(&params, (struct buf_params) { })) {
                retval = -ENOMEM;
                goto cleanup;
        }

diff --git a/src/logger/logger.c b/src/logger/logger.c
index 75487ec..bca4641 100644 (file)
--- a/src/logger/logger.c
+++ b/src/logger/logger.c
@@ -224,6 +224,16 @@ void check_if_fd_limit_reached(struct logger *server, int err)
                printf("ERROR: not enough memory either, please check platform settings as the daemon is seriously resource-starved!\n");
 }
 
+void flush_logfile_timely(struct log_file *file, struct timespec ts, int flush_time)
+{
+       if (file->buffer.position > 0) {
+               if (ts.tv_sec - file->buffer.oldest_log.tv_sec +
+                                       (ts.tv_nsec > file->buffer.oldest_log.tv_nsec ? 1 : 0) >
+                               flush_time)
+                       logfile_flush(file);
+       }
+}
+
 void reader_notify_losing_log(const dlogutil_entry_s *le, void *reader_)
 {
        struct reader_pipe *reader = (struct reader_pipe *) reader_;
@@ -552,9 +562,6 @@ static bool cond_service_reader_pipe(void *ptr, void *user_data)
        struct reader_pipe *reader = (struct reader_pipe *)ptr;
        struct logger *logger = (struct logger *)user_data;
 
-       if (!logger->exiting && reader_should_buffer(reader, &logger->buf_params, logger->time.mono))
-               return false;
-
        int r = print_out_logs(reader, logger->time);
 
        if (r > 0) {
@@ -583,6 +590,8 @@ static bool cond_service_reader_pipe(void *ptr, void *user_data)
                 * like we can do anything about it either */
        }
 
+       flush_logfile_timely(&reader->file, logger->time.mono, logger->buf_params.time);
+
        return false;
 }
 
@@ -621,6 +630,7 @@ static bool cond_service_reader_logger(void *ptr, void *user_data)
                 * like we can do anything about it either */
        }
 
+       reader_logger_flush(reader, logger->time.mono, logger->buf_params.time);
        return false;
 }
 
@@ -1239,7 +1249,7 @@ void parse_logfile_config(void *value, void *userdata)
        char *configline = (char *) value;
 
        __attribute__((cleanup(free_dlogutil_line_params))) struct dlogutil_line_params params;
-       if (!initialize_dlogutil_line_params(&params))
+       if (!initialize_dlogutil_line_params(&params, server->buf_params))
                return;
 
        get_dlogutil_line_params(configline, &params);

diff --git a/src/logger/logger_internal.h b/src/logger/logger_internal.h
index 11bdd58..998c822 100644 (file)
--- a/src/logger/logger_internal.h
+++ b/src/logger/logger_internal.h
@@ -75,13 +75,13 @@ enum {
 enum {
        BUF_PARAM_TIME_MIN = 0,
        BUF_PARAM_TIME_MAX = 3600,
-       BUF_PARAM_TIME_DEFAULT = 1,
+       BUF_PARAM_TIME_DEFAULT = 10,
 };
 
 enum {
        BUF_PARAM_BYTES_MIN = 0,
-       BUF_PARAM_BYTES_MAX = 65536,
-       BUF_PARAM_BYTES_DEFAULT = 100
+       BUF_PARAM_BYTES_MAX = 1 << 24,
+       BUF_PARAM_BYTES_DEFAULT = 1 << 20
 };
 
 enum {
@@ -167,6 +167,7 @@ int service_writer_syslog(struct logger* server, struct writer* wr, struct epoll
 void logger_add_writer(struct logger* l, struct writer* wr);
 int create_fifo_fds(struct logger *server, int fifo_id, int *write_fd, int *read_fd, bool dump);
 int add_reader_pipe(struct logger *server, struct reader_pipe *reader);
+void flush_logfile_timely(struct log_file *file, struct timespec ts, int flush_time);
 
 #ifdef __cplusplus
 }

diff --git a/src/logger/reader_logger.c b/src/logger/reader_logger.c
index 1f4fb52..14d393c 100644 (file)
--- a/src/logger/reader_logger.c
+++ b/src/logger/reader_logger.c
@@ -17,6 +17,11 @@ static void subreader_logger_metrics_free(void *userdata)
        // nothing to do; we're just a wrapper over a weak (shared) pointer
 }
 
+static void subreader_logger_metrics_flush(void *userdata, struct timespec ts, int flush_time)
+{
+       // nothing to do either; no such concept as flushing metrics
+}
+
 static void subreader_logger_file_apply_log(const struct subreader_logger *srl, const struct dlogutil_entry *due)
 {
        assert(srl);
@@ -36,6 +41,14 @@ static void subreader_logger_file_free(void *userdata)
        logfile_free(&srlf->file);
 }
 
+static void subreader_logger_file_flush(void *userdata, struct timespec ts, int flush_time)
+{
+       struct subreader_logger_file *const srlf = (struct subreader_logger_file *) userdata;
+       assert(srlf);
+
+       flush_logfile_timely(&srlf->file, ts, flush_time);
+}
+
 static void subreader_logger_free(void *sub, void *userdata)
 {
        struct subreader_logger *const srl = (struct subreader_logger *) sub;
@@ -61,6 +74,23 @@ static void subreader_logger_apply_log(void *sub, void *userdata)
 
        srl->sub_apply_log(srl, due);
 }
+
+struct flush_args {
+       struct timespec ts;
+       int flush_time;
+};
+
+static void subreader_logger_flush(void *sub, void *userdata)
+{
+       struct subreader_logger *const srl = (struct subreader_logger *) sub;
+       assert(srl);
+       assert(srl->sub_flush);
+
+       struct flush_args *const args = (struct flush_args *) userdata;
+
+       srl->sub_flush(srl->sub_userdata, args->ts, args->flush_time);
+}
+
 void reader_logger_free(struct reader_logger *reader)
 {
        if (!reader)
@@ -156,6 +186,7 @@ int reader_logger_add_subreader_file(struct reader_logger *reader, dlogutil_filt
        srl->sub_userdata = srlf;
        srl->sub_destroy = subreader_logger_file_free;
        srl->sub_apply_log = subreader_logger_file_apply_log;
+       srl->sub_flush = subreader_logger_file_flush;
        srl->filter = log_filter_move(filter);
 
        list_add(&reader->subs, srl);
@@ -183,6 +214,7 @@ int reader_logger_add_subreader_metrics(struct reader_logger *reader, struct qos
        srl->sub_userdata = srlm;
        srl->sub_destroy = subreader_logger_metrics_free;
        srl->sub_apply_log = subreader_logger_metrics_apply_log;
+       srl->sub_flush = subreader_logger_file_flush;
        srl->filter = filter;
 
        list_add(&reader->subs, srl);
@@ -244,3 +276,10 @@ int reader_logger_init(struct reader_logger **reader, log_id_t buf_id, struct lo
        return 0;
 }
 
+void reader_logger_flush(struct reader_logger *reader, struct timespec now_mono, int flush)
+{
+       list_foreach(reader->subs, &(struct flush_args) {
+               .ts = now_mono,
+               .flush_time = flush,
+       }, subreader_logger_flush);
+}

diff --git a/src/logger/reader_logger.h b/src/logger/reader_logger.h
index ea7ef4a..37a4245 100644 (file)
--- a/src/logger/reader_logger.h
+++ b/src/logger/reader_logger.h
@@ -14,6 +14,7 @@ struct subreader_logger_metrics {
 
 struct subreader_logger {
        void (*sub_apply_log)(const struct subreader_logger *srl, const struct dlogutil_entry *due);
+       void (*sub_flush)(void *sub_userdata, struct timespec ts, int flush_time);
        void (*sub_destroy)(void *sub_userdata);
        void *sub_userdata;
        dlogutil_filter_options_s *filter;
@@ -32,3 +33,4 @@ int reader_logger_add_subreader_file(struct reader_logger *reader, dlogutil_filt
 int reader_logger_add_subreader_metrics(struct reader_logger *reader, struct qos_module *qos);
 void reader_logger_free(struct reader_logger *reader);
 void reader_logger_cleanup(struct reader_logger *const *ptr);
+void reader_logger_flush(struct reader_logger *reader, struct timespec now_mono, int flush);

diff --git a/src/logger/reader_pipe.c b/src/logger/reader_pipe.c
index d336ddb..330bd82 100644 (file)
--- a/src/logger/reader_pipe.c
+++ b/src/logger/reader_pipe.c
@@ -111,40 +111,6 @@ int reader_pipe_init_with_writer(struct reader_pipe **reader, struct writer *wri
        return 0;
 }
 
-
-uint64_t reader_buffered_space(const struct reader_pipe *reader)
-{
-       assert(reader);
-       assert(reader->buf_ptr);
-       return log_storage_reader_get_ready_bytes(reader->log_storage_reader_ptr);
-}
-
-int reader_is_bufferable(const struct reader_pipe *reader)
-{
-       assert(reader);
-       return reader->buf_ptr && reader->file.path != NULL;
-}
-
-int reader_ms_since(const struct reader_pipe *reader, struct timespec *ts)
-{
-       return (ts->tv_sec - reader->last_read_time.tv_sec) * 1000 + (ts->tv_nsec - reader->last_read_time.tv_nsec) / 1000000;
-}
-
-int reader_should_buffer(struct reader_pipe *reader, const struct buf_params *buf_params, struct timespec now)
-{
-       assert(reader);
-       assert(buf_params);
-
-       if (!reader_is_bufferable(reader))
-               return 0;
-
-       if (reader_buffered_space(reader) < (uint64_t)buf_params->bytes && reader_ms_since(reader, &now) < (buf_params->time * 1000))
-               return 1;
-
-       reader->last_read_time = now;
-       return 0;
-}
-
 int reader_print_out_single_log(struct reader_pipe *reader, const dlogutil_entry_s *dlogutil_entry)
 {
        assert(reader);

diff --git a/src/logger/reader_pipe.h b/src/logger/reader_pipe.h
index 8c2014b..8c011dc 100644 (file)
--- a/src/logger/reader_pipe.h
+++ b/src/logger/reader_pipe.h
@@ -7,11 +7,7 @@
 #include "queued_entry_timestamp.h"
 
 struct writer;
-
-struct buf_params {
-       int bytes;
-       int time;
-};
+struct buf_params;
 
 struct reader_pipe {
        struct log_buffer *buf_ptr;
@@ -35,9 +31,3 @@ int reader_print_out_single_log(struct reader_pipe *reader, const dlogutil_entry
 int print_out_logs(struct reader_pipe *reader, struct now_t _time);
 void reader_pipe_free(struct reader_pipe *reader);
 void reader_pipe_cleanup(struct reader_pipe *const *ptr);
-
-#ifdef UNIT_TEST
-uint64_t reader_buffered_space(const struct reader_pipe *reader);
-int reader_is_bufferable(const struct reader_pipe *reader);
-int reader_ms_since(const struct reader_pipe *reader, struct timespec *ts);
-#endif

diff --git a/src/logutil/logutil.c b/src/logutil/logutil.c
index e9ed86f..d23568f 100644 (file)
--- a/src/logutil/logutil.c
+++ b/src/logutil/logutil.c
@@ -65,6 +65,8 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
        *mode = DLOGUTIL_MODE_CONTINUOUS;
        *dump_size = DLOGUTIL_MAX_DUMP_SIZE;
 
+       bool buffer_made = false;
+
        while (1) {
                static const struct option long_options[] = {
                        {"tid"    , required_argument, NULL,   0},
@@ -76,7 +78,7 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
                        {0}
                };
                int err_arg_nondigit = 0;
-               int option = getopt_long(argc, argv, "cdmt:gsf:r:n:v:b:u:h", long_options, NULL);
+               int option = getopt_long(argc, argv, "cdmt:gsf:r:n:v:b:u:e:h", long_options, NULL);
 
                if (option < 0)
                        break;
@@ -186,6 +188,21 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
                        if (sscanf(optarg, "%zu", &l_file->max_rotated) != 1)
                                err_arg_nondigit = 1;
                        break;
+               case 'e': {
+                       size_t buf_size;
+                       if (buffer_made) {
+                               ERR("Multiple -e\n");
+                               return -EINVAL;
+                       }
+                       if (sscanf(optarg, "%zu", &buf_size) != 1)
+                               err_arg_nondigit = 1;
+                       if (buf_size > 0)
+                               if (!logfile_init_buffer(l_file, buf_size))
+                                       ERR("Warning: failed to create the write buffer\n");
+                                       // Not an error, since we can continue
+                       buffer_made = true;
+                       break;
+               }
                case 'h':
                        show_help(argv[0], true);
                        return 1;
@@ -222,6 +239,11 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
        if (*enabled_buffers == 0)
                *enabled_buffers = default_buffers;
 
+       if (!buffer_made && *mode == DLOGUTIL_MODE_DUMP)
+               if (!logfile_init_buffer(l_file, DEFAULT_WRITE_BUFFER_SIZE))
+                       ERR("Warning: failed to create write buffer\n");
+                       // Again, not an error, since we can continue
+
        return 0;
 
 enomem:
@@ -409,12 +431,20 @@ static int do_print(dlogutil_mode_e mode, unsigned int dump_size, int enabled_bu
                return 1;
        }
 
+       const bool file_should_flush = l_file->buffer.size > 0 && mode != DLOGUTIL_MODE_DUMP;
+       bool file_might_flush = file_should_flush;
        for (;;) {
                __attribute__((cleanup(free_ptr))) dlogutil_entry_s *entry;
 
-               r = dlogutil_get_log(state, -1, &entry);
+               r = dlogutil_get_log(state, file_might_flush ? 0 : -1, &entry);
                if (r == TIZEN_ERROR_NO_DATA)
                        return 0;
+               else if (r == TIZEN_ERROR_TIMED_OUT) {
+                       assert(file_might_flush);
+                       file_might_flush = false;
+                       logfile_flush(l_file);
+                       continue;
+               }
                else if (r < 0) {
                        errno = -r;
                        ERR("Error while retrieving a log: %m");
@@ -428,6 +458,8 @@ static int do_print(dlogutil_mode_e mode, unsigned int dump_size, int enabled_bu
                        return 1;
                } else if (r > 0)
                        return 0; // Quiet failure for some reason
+
+               file_might_flush = file_should_flush;
        }
 }
 

diff --git a/src/logutil/logutil_doc.h b/src/logutil/logutil_doc.h
index e9151f3..94921d0 100644 (file)
--- a/src/logutil/logutil_doc.h
+++ b/src/logutil/logutil_doc.h
@@ -36,6 +36,8 @@ If you specify any other tag without priority, the priority defaults to V
 
 #include <stdbool.h>
 
+#define DEFAULT_WRITE_BUFFER_SIZE 1048576
+
 static void show_help(const char *cmd, bool requested_by_user)
 {
        static const char *format_str = "Usage: %s [options] [filterspecs]"
@@ -55,6 +57,10 @@ static void show_help(const char *cmd, bool requested_by_user)
                "                    the default set is main + system + apps\n"
                "  -u <size>         Sets the size of sort buffer (0 to disable sorting)\n"
                "                    Smaller is faster but lowers sorting quality\n"
+               "  -e <size>         Sets the size of the write buffer (0 to disable buffering)\n"
+               "                    Larger decreases the amount of writes in exchange for larger memory usage\n"
+               "                    and getting logs later (especially in continuous and monitor modes!)\n"
+               "                    Default is " STRINGIFY(DEFAULT_WRITE_BUFFER_SIZE) " in the dump mode and 0 otherwise\n"
                "  --pid <pid>       Filter messages by process id\n"
                "  --tid <tid>       Filter messages by thread id\n"
                "  --color <when>    Toggle color coding of headers (when can be 'always', 'auto' or 'never').\n"

diff --git a/src/shared/log_file.c b/src/shared/log_file.c
index 35c81aa..47f4ca1 100644 (file)
--- a/src/shared/log_file.c
+++ b/src/shared/log_file.c
@@ -48,6 +48,27 @@ void logfile_init(struct log_file *l_file)
        l_file->colors_auto = true;
        l_file->prev_sec = INT_MIN;
        l_file->prev_nsec = INT_MIN;
+       l_file->buffer = (struct log_write_buffer) { };
+}
+
+bool logfile_init_buffer(struct log_file *l_file, size_t buf_size)
+{
+       assert(l_file);
+       assert(l_file->buffer.size == 0);
+
+       if (buf_size <= 0)
+               return true;
+
+       l_file->buffer.data = malloc(buf_size);
+       if (!l_file->buffer.data) {
+               l_file->buffer = (struct log_write_buffer) { };
+               return false;
+       }
+
+       l_file->buffer.position = 0;
+       l_file->buffer.size = buf_size;
+
+       return true;
 }
 
 static void logfile_set_should_close(struct log_file *l_file, int on_off)
@@ -103,6 +124,13 @@ void logfile_free(struct log_file *l_file)
                free(l_file->path);
                l_file->path = NULL;
        }
+       if (l_file->buffer.data) {
+               logfile_flush(l_file);
+               free(l_file->buffer.data);
+               l_file->buffer.data = NULL;
+               l_file->buffer.position = 0;
+               l_file->buffer.size = 0;
+       }
        logfile_close_if_needed(l_file);
 }
 
@@ -143,6 +171,7 @@ void logfile_move(struct log_file *to, struct log_file *from)
 
        from->path = NULL;
        from->fd = -1;
+       from->buffer = (struct log_write_buffer) { };
 }
 
 /**
@@ -180,7 +209,12 @@ int logfile_rotate_needed(struct log_file *l_file)
                return 0;
 
        logfile_update_fsize(l_file);
-       return BtoKiB(l_file->size) > l_file->rotate_size_kbytes;
+
+       size_t size = l_file->size;
+       if (l_file->buffer.data)
+               size += l_file->buffer.position;
+
+       return BtoKiB(size) > l_file->rotate_size_kbytes;
 }
 
 /**
@@ -197,6 +231,9 @@ void logfile_do_rotate(struct log_file *file)
        char path0[PATH_MAX];
        char path1[PATH_MAX];
 
+       if ((errno = -logfile_flush(file)) > 0)
+               ERR("while flushing log file");
+
        for (i = file->max_rotated ; i > 0 ; i--) {
                snprintf(path1, PATH_MAX, "%s.%d", file->path, i);
                if (i - 1 == 0)
@@ -217,6 +254,19 @@ static void logfile_add_timestamp(struct log_file *file, struct timespec ts)
        file->prev_nsec = ts.tv_nsec;
 }
 
+int logfile_flush(struct log_file *file)
+{
+       assert(file);
+
+       if (!file->buffer.data)
+               return 0;
+
+       int written = write(file->fd, file->buffer.data, file->buffer.position);
+       if (write > 0)
+               file->buffer.position = 0; // TODO: data loss possibility here
+       return written;
+}
+
 /**
  * @brief Write with rotation
  * @details Writes the entry to given file, automatically handling file rotation
@@ -249,7 +299,7 @@ int logfile_write_with_rotation(const dlogutil_entry_s *e, struct log_file *file
                } else {
                        msg.header.len = r + 1 + sizeof *e;
 
-                       written_bytes += log_print_log_line(file->format, file->fd, &msg.header);
+                       written_bytes += log_print_log_line(file->format, file->fd, &msg.header, &file->buffer);
 
                        if (written_bytes < 0) {
                                ERR("unable to write out-of-order message %m");
@@ -258,7 +308,7 @@ int logfile_write_with_rotation(const dlogutil_entry_s *e, struct log_file *file
                }
        }
 
-       written_bytes += log_print_log_line(file->format, file->fd, e);
+       written_bytes += log_print_log_line(file->format, file->fd, e, &file->buffer);
        if (written_bytes <= 0)
                return 1;
        file->size += written_bytes;

diff --git a/src/shared/logprint.c b/src/shared/logprint.c
index 02a3680..4d5dfdc 100644 (file)
--- a/src/shared/logprint.c
+++ b/src/shared/logprint.c
@@ -810,15 +810,46 @@ struct timespec entry_get_ts(const dlogutil_entry_s *entry, bool sent, bool mono
        return ret;
 }
 
-static int log_print_line_format_json(int fd, const dlogutil_entry_s *entry)
+static int resolve_write(int fd, struct log_write_buffer *wrbuf, const char *realbuf, size_t realsize)
+{
+       if (realbuf != wrbuf->data + wrbuf->position) {
+               if (wrbuf->position > 0) {
+                       int res = write(fd, wrbuf->data, wrbuf->position);
+                       if (res <= 0)
+                               return 0;
+               }
+
+               int res;
+               if (realsize < wrbuf->size) {
+                       memcpy(wrbuf->data, realbuf, realsize);
+                       clock_gettime(CLOCK_MONOTONIC, &wrbuf->oldest_log);
+                       res = wrbuf->position = realsize;
+               } else {
+                       res = write(fd, realbuf, realsize);
+                       wrbuf->position = 0;
+               }
+               return res > 0 ? res : 0;
+       } else {
+               if (wrbuf->position == 0)
+                       clock_gettime(CLOCK_MONOTONIC, &wrbuf->oldest_log);
+               wrbuf->position += realsize;
+               return realsize;
+       }
+}
+
+static int log_print_line_format_json(int fd, const dlogutil_entry_s *entry, struct log_write_buffer *wrbuf)
 {
        size_t buflen;
-       __attribute__ ((cleanup(free_ptr))) char *const buf = log_format_json(NULL, 0, entry, &buflen, entry->msg, entry->msg + entry->tag_len + 1);
+       // TODO: This could really use an improvement
+       char *const buf = log_format_json(wrbuf->data + wrbuf->position, wrbuf->size - wrbuf->position, entry, &buflen, entry->msg, entry->msg + entry->tag_len + 1);
        if (!buf)
                return -1;
+       bool to_free = buf != (wrbuf->data + wrbuf->position);
 
-       int res = write(fd, buf, buflen);
-       return res < 0 ? 0 : res;
+       int res = resolve_write(fd, wrbuf, buf, buflen);
+       if (to_free)
+               free(buf);
+       return res;
 }
 
 #define METADATA_MAX_LEN 128
@@ -1030,6 +1061,7 @@ static int format_metadata_long(const dlogutil_entry_s *entry, char *prefix, cha
 #define STATIC_BUFFER_SIZE 512
 
 typedef struct {
+       bool buf_created;
        char *buf_start;
        char *buf_position;
        const char *no_color_suffix;
@@ -1037,23 +1069,24 @@ typedef struct {
        size_t prefix_len;
        size_t suffix_len;
        size_t no_color_suffix_len;
-       char static_buffer[STATIC_BUFFER_SIZE];
        char prefix[COLORED_METADATA_MAX_LEN];
        char suffix[COLORED_METADATA_MAX_LEN];
 } print_buffer;
 
-static int print_buffer_init(print_buffer *buffer, size_t message_len, size_t number_of_lines)
+static int print_buffer_init(print_buffer *buffer, size_t message_len, size_t number_of_lines, struct log_write_buffer *wrbuf)
 {
        assert(buffer);
 
        size_t needed_space = message_len + number_of_lines * (strlen(buffer->prefix) + strlen(buffer->suffix) + strlen(buffer->no_color_suffix)) + 1;
 
-       if (needed_space <= STATIC_BUFFER_SIZE) {
-               buffer->buf_start = buffer->static_buffer;
+       if (needed_space <= wrbuf->size - wrbuf->position) {
+               buffer->buf_start = wrbuf->data + wrbuf->position;
+               buffer->buf_created = false;
        } else {
                buffer->buf_start = malloc(needed_space);
                if (!buffer->buf_start)
                        return -1;
+               buffer->buf_created = true;
        }
 
        buffer->allocated_space = needed_space;
@@ -1066,8 +1099,9 @@ static int print_buffer_init(print_buffer *buffer, size_t message_len, size_t nu
 
 static void print_buffer_destroy(print_buffer *buffer)
 {
-       if (buffer->buf_start != buffer->static_buffer)
+       if (buffer->buf_created)
                free(buffer->buf_start);
+       buffer->buf_created = false;
 }
 
 static size_t print_buffer_remaining_space(print_buffer *buffer)
@@ -1161,6 +1195,7 @@ static size_t scan_lines(const char *message, bool split_on_eol)
  * @param[in] p_format The format to use
  * @param[in] fd The file descriptor to write to
  * @param[in] entry The entry to print
+ * @param[in,out] buf The write buffer to use
  * @returns On success, the number of bytes written; else a specific value
  * @retval -1 Memory allocation failure
  * @retval 0 Write failed
@@ -1168,12 +1203,41 @@ static size_t scan_lines(const char *message, bool split_on_eol)
 int log_print_log_line(
        struct log_format p_format,
        int fd,
-       const dlogutil_entry_s *entry)
+       const dlogutil_entry_s *entry,
+       struct log_write_buffer *wrbuf)
 {
        assert(entry);
+       assert(wrbuf);
+
+       /* TODO: Return values are super iffy now.
+        * The issue is that we sometimes don't write the log, but we still might want to return
+        * a positive value. Right now we do some weird voodoo with the return values,
+        * which means that the positive random are kinda random. */
+
+       if (wrbuf->data == NULL) {
+               const size_t size = 512;
+               wrbuf->data = alloca(size);
+               wrbuf->position = 0;
+               wrbuf->size = size;
+
+               int r = log_print_log_line(p_format, fd, entry, wrbuf);
+               if (r == -1)
+                       return -1;
+
+               if (r > 0 && wrbuf->position != 0) {
+                       r = write(fd, wrbuf->data, wrbuf->position);
+                       if (r < 0)
+                               r = 0;
+               }
+
+               wrbuf->data = NULL;
+               wrbuf->position = 0;
+               wrbuf->size = 0;
+               return r;
+       }
 
        if (p_format.format == FORMAT_JSON)
-               return log_print_line_format_json(fd, entry);
+               return log_print_line_format_json(fd, entry, wrbuf);
 
        const struct format_info {
                format_function format_metadata;
@@ -1219,14 +1283,13 @@ int log_print_log_line(
                --message_len;
        const char *message_end = message + message_len;
 
-       if (print_buffer_init(&buffer, message_len, number_of_lines) != 0)
+       if (print_buffer_init(&buffer, message_len, number_of_lines, wrbuf) != 0)
                return -1;
 
        while (message < message_end)
                message += print_buffer_add_line(&buffer, message, message_end - message, format->split_lines);
 
-       int res = write(fd, buffer.buf_start, buffer.buf_position - buffer.buf_start);
-       return res < 0 ? 0 : res;
+       return resolve_write(fd, wrbuf, buffer.buf_start, buffer.buf_position - buffer.buf_start);
 }
 
 /**

diff --git a/src/tests/log_file.c b/src/tests/log_file.c
index 56ee1b7..95fb460 100644 (file)
--- a/src/tests/log_file.c
+++ b/src/tests/log_file.c
@@ -72,7 +72,7 @@ int __wrap_snprintf(char *str, size_t size, const char *format, ...)
 
 static int log_print_log_line_ret;
 static bool log_print_log_line_correct_color;
-int __wrap_log_print_log_line(struct log_format p_format, int fd, const dlogutil_entry_s *entry)
+int __wrap_log_print_log_line(struct log_format p_format, int fd, const dlogutil_entry_s *entry, struct log_write_buffer *buf)
 {
        assert(fd == 0xFD);
        assert(p_format.color == log_print_log_line_correct_color);

diff --git a/src/tests/logger.c b/src/tests/logger.c
index 146b0e4..71203d3 100644 (file)
--- a/src/tests/logger.c
+++ b/src/tests/logger.c
@@ -25,10 +25,6 @@ int service_socket_dummy(struct logger *server, struct writer *wr, struct dlog_c
 int socket_initialize(struct sock_data *sock, struct log_buffer *buffer, service_socket_t service_socket, struct socket_config_data *data);
 void dispatch_event_sock(struct logger *server, struct epoll_event *event, void *userdata);
 void socket_close(struct sock_data *sock);
-uint64_t reader_buffered_space(const struct reader_pipe *reader);
-int reader_is_bufferable(const struct reader_pipe *reader);
-int reader_ms_since(const struct reader_pipe *reader, struct timespec *ts);
-int reader_should_buffer(struct reader_pipe *reader, const struct buf_params *buf_params, struct timespec now);
 void reader_pipe_free(struct reader_pipe *reader);
 int buffer_append(const dlogutil_entry_s *entry, struct log_buffer *b);
 int print_out_logs(struct reader_pipe *reader, struct now_t time);
@@ -794,86 +790,22 @@ int main()
        sock.fd_entity.fd = 0;
        socket_close(&sock);
 
-       struct reader_pipe reader = {
-               .log_storage_reader_ptr = (log_storage_reader *)7,
-               .last_read_time = {
-                       .tv_sec = 0,
-                       .tv_nsec = 100000000,
-               },
-               .file = {},
-       };
-
-       assert(!reader_is_bufferable(&reader));
-
-       reader.buf_ptr = (struct log_buffer *)0x5BU;
-       assert(!reader_is_bufferable(&reader));
-
-       reader.buf_ptr = NULL;
-       reader.file.path = "/dev/null";
-       assert(!reader_is_bufferable(&reader));
-
-       reader.buf_ptr = (struct log_buffer *)0x5BU;
-       assert(reader_is_bufferable(&reader));
-
-       assert(reader_buffered_space(&reader) == 7);
-
-       assert(reader_ms_since(&reader, &(struct timespec) {
-               .tv_sec = 1,
-               .tv_nsec = 0,
-       }) == 900);
-
-       struct buf_params params = {
-               .bytes = 100,
-               .time = 0,
-       };
-
-       reader.buf_ptr = NULL;
-       assert(!reader_should_buffer(&reader, &params, (struct timespec) {
-               .tv_sec = 1,
-               .tv_nsec = 0,
-       }));
-       assert(reader.last_read_time.tv_sec == 0 && reader.last_read_time.tv_nsec == 100000000);
-
-       reader.buf_ptr = (struct log_buffer *)0x5BU;
-       assert(!reader_should_buffer(&reader, &params, (struct timespec) {
-               .tv_sec = 1,
-               .tv_nsec = 0,
-       }));
-       assert(reader.last_read_time.tv_sec == 1 && reader.last_read_time.tv_nsec == 0);
-
-       params.time = 1;
-       params.bytes = 0;
-       assert(!reader_should_buffer(&reader, &params, (struct timespec) {
-               .tv_sec = 1,
-               .tv_nsec = 500000000,
-       }));
-       assert(reader.last_read_time.tv_sec == 1 && reader.last_read_time.tv_nsec == 500000000);
-
-       params.bytes = 100;
-       assert(reader_should_buffer(&reader, &params, (struct timespec) {
-               .tv_sec = 2,
-               .tv_nsec = 0,
-       }));
-       assert(reader.last_read_time.tv_sec == 1 && reader.last_read_time.tv_nsec == 500000000);
-
-       reader_pipe_free(NULL);
-
-       struct reader_pipe *reader2 = calloc(1, sizeof(struct reader_pipe));
-       assert(reader2);
-       reader2->file.fd = 1;
-       reader_pipe_free(reader2);
-       assert(last_free == reader2 && last_logfile_free_fd == 1);
-
-       reader2 = calloc(1, sizeof(struct reader_pipe));
-       assert(reader2);
-       reader2->file.fd = 3;
-       reader2->common.fd_entity_sink = ent;
-       assert(reader2->common.fd_entity_sink.fd == 2);
-       reader2->common.fd_entity_source.fd = 1;
-       reader2->log_storage_reader_ptr = (log_storage_reader *)13;
+       struct reader_pipe *reader = calloc(1, sizeof(struct reader_pipe));
+       assert(reader);
+       reader->file.fd = 1;
+       reader_pipe_free(reader);
+       assert(last_free == reader && last_logfile_free_fd == 1);
+
+       reader = calloc(1, sizeof(struct reader_pipe));
+       assert(reader);
+       reader->file.fd = 3;
+       reader->common.fd_entity_sink = ent;
+       assert(reader->common.fd_entity_sink.fd == 2);
+       reader->common.fd_entity_source.fd = 1;
+       reader->log_storage_reader_ptr = (log_storage_reader *)13;
        closed[0] = closed[1] = false;
-       reader_pipe_free(reader2);
-       assert(last_free == reader2 && last_logfile_free_fd == 3);
+       reader_pipe_free(reader);
+       assert(last_free == reader && last_logfile_free_fd == 3);
        assert(closed[0] && closed[1]);
        assert(reader_released);
 

diff --git a/src/tests/logprint.c b/src/tests/logprint.c
index ed87f57..ec6163e 100644 (file)
--- a/src/tests/logprint.c
+++ b/src/tests/logprint.c
@@ -162,7 +162,7 @@ void check_logprint_testcases(struct dlogutil_entry_with_msg *entry, const struc
                assert(log_print_log_line((struct log_format){
                        .format = tests[i].format,
                        .color = tests[i].color_enabled,
-               }, 0, &entry->header) > 0);
+               }, 0, &entry->header, &(struct log_write_buffer) { }) > 0);
                fprintf(stderr, "format=%d, expected %s<, got %s<", tests[i].format, tests[i].result, buffer);
                assert(!strcmp(tests[i].result, buffer));
        }
@@ -476,6 +476,43 @@ void check_log_print_log_line()
        CHECK_LOGPRINT_TESTCASES_INVALID("BASIC TAG\0Basic message.", tests_fixup_pipe);
 }
 
+void check_log_print_log_line_buffer()
+{
+       struct dlogutil_entry_with_msg entry;
+       const char tag_msg[] = "tag\0msg";
+       const char msg[] = "msg\n";
+       standard_test_msg(&entry, tag_msg, sizeof(tag_msg));
+
+       char data[1234];
+       struct log_write_buffer wbuf = {
+               .data = data,
+               .position = 0,
+               .size = sizeof(data),
+       };
+
+       fake_write = true;
+       buffer[0] = '\0';
+
+       for (int cpos = 0; cpos < sizeof(data); cpos += strlen(msg)) {
+               assert(wbuf.position == cpos);
+               assert(strlen(buffer) == 0);
+               assert(log_print_log_line((struct log_format){
+                       .format = FORMAT_RAW,
+                       .color = false,
+               }, 0, &entry.header, &wbuf) > 0);
+       }
+
+       assert(wbuf.position == strlen(msg));
+       assert(memcmp(wbuf.data, msg, strlen(msg)) == 0);
+
+       int total_count = sizeof(data) / strlen(msg);
+       assert(strlen(buffer) == total_count * strlen(msg));
+       for (int i = 0; i < total_count; ++i)
+               assert(memcmp(buffer + i * strlen(msg), msg, strlen(msg)) == 0);
+
+       fake_write = false;
+}
+
 char *json_escape_string(char *in);
 void check_json_escape_string_testcase(char *in, char *correct)
 {
@@ -688,18 +725,18 @@ void check_syscall_failure_handling()
        };
 
        fail_alloc = true;
-       assert(-1 == log_print_log_line(format, 0, &entry.header));
+       assert(-1 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
        fail_alloc = false;
 
        fail_localtime_r = true;
-       assert(-1 == log_print_log_line(format, 0, &entry.header));
+       assert(-1 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
        fail_localtime_r = false;
 
        partial_write = -1;
-       assert(0 == log_print_log_line(format, 0, &entry.header));
+       assert(0 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
 
        partial_write = 17;
-       assert(17 == log_print_log_line(format, 0, &entry.header));
+       assert(17 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
 
        partial_write = 0;
        log_filter_free(filter);
@@ -840,6 +877,7 @@ int main()
        check_get_format_sorting();
        check_filter_pri_to_char();
        check_log_print_log_line();
+       check_log_print_log_line_buffer();
        check_invalid_input();
        check_syscall_failure_handling();
        check_json();

diff --git a/tests/dlog_test.in b/tests/dlog_test.in
index ce45dbd..3037941 100644 (file)
--- a/tests/dlog_test.in
+++ b/tests/dlog_test.in
@@ -133,7 +133,7 @@ mkdir -p "$RUNTIME_FILTERS_DIR"
 
 # Start the daemon
 if [ $type == "pipe" ]; then
-       dlog_logger -b 99 -t 0 &
+       dlog_logger &
        LOGGER=$!
        sleep 1
 fi
@@ -917,7 +917,7 @@ if [ $quick -ne 1 ]; then
                sleep 1
                ULIMIT_CURRENT=`ulimit -n`
                ulimit -n 30
-               dlog_logger -b 99 -t 600 &> /dev/null &
+               dlog_logger &> /dev/null &
                LOGGER=$!
                ulimit -n $ULIMIT_CURRENT