Move log filtering out of log writing

This also adds a nice bonus -- now, in dlogutil, the incoming logs
are only filtered once, and in one place.

Change-Id: I443b48967344353b0a92731295d11a369d9de2fb

diff --git a/Makefile.am b/Makefile.am
index f0a65f7..312198c 100644 (file)
--- a/Makefile.am
+++ b/Makefile.am
@@ -238,11 +238,11 @@ src_tests_dynamic_config_LDFLAGS = $(AM_LDFLAGS) -lpthread -Wl,--wrap=read,--wra
 
 src_tests_sort_vector_SOURCES = src/tests/sort_vector.c src/logutil/sort_vector.c
 src_tests_sort_vector_CFLAGS = $(check_CFLAGS)
-src_tests_sort_vector_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=log_config_get_int,--wrap=log_should_print_line,--wrap=logfile_write_with_rotation,--wrap=log_entry_is_earlier,--wrap=free
+src_tests_sort_vector_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=log_config_get_int,--wrap=logfile_write_with_rotation,--wrap=log_entry_is_earlier,--wrap=free
 
 src_tests_fd_info_SOURCES = src/tests/fd_info.c src/logutil/fd_info.c
 src_tests_fd_info_CFLAGS = $(check_CFLAGS)
-src_tests_fd_info_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=sort_vector_push,--wrap=logfile_write_with_rotation,--wrap=malloc,--wrap=free,--wrap=close,--wrap=extract_timestamp
+src_tests_fd_info_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=sort_vector_push,--wrap=logfile_write_with_rotation,--wrap=malloc,--wrap=free,--wrap=close,--wrap=extract_timestamp,--wrap=log_should_print_line
 
 src_tests_fdi_logger_SOURCES = src/tests/fdi_logger.c src/logutil/fdi_logger.c src/shared/ptrs_list.c src/shared/logcommon.c
 src_tests_fdi_logger_CFLAGS = $(check_CFLAGS)
@@ -270,7 +270,7 @@ src_tests_libdlog_base_LDFLAGS = $(AM_LDFLAGS) -lpthread -Wl,--wrap=log_config_r
 
 src_tests_log_file_SOURCES = src/tests/log_file.c src/shared/log_file.c
 src_tests_log_file_CFLAGS = $(check_CFLAGS)
-src_tests_log_file_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=strdup,--wrap=free,--wrap=memcpy,--wrap=snprintf,--wrap=open,--wrap=fstat,--wrap=rename,--wrap=log_should_print_line,--wrap=extract_timestamp,--wrap=log_print_log_line,--wrap=log_buffer_get_tag
+src_tests_log_file_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=strdup,--wrap=free,--wrap=memcpy,--wrap=snprintf,--wrap=open,--wrap=fstat,--wrap=rename,--wrap=extract_timestamp,--wrap=log_print_log_line,--wrap=log_buffer_get_tag
 
 src_tests_queued_entry_SOURCES = src/tests/queued_entry.c src/shared/queued_entry.c src/shared/queued_entry_timestamp.c src/shared/parsers.c src/shared/translate_syslog.c src/shared/logconfig.c src/shared/logcommon.c
 src_tests_queued_entry_CFLAGS = $(check_CFLAGS)

diff --git a/include/log_file.h b/include/log_file.h
index dc7e9f9..85639d9 100644 (file)
--- a/include/log_file.h
+++ b/include/log_file.h
@@ -54,7 +54,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_write_with_rotation(const struct logger_entry *e, struct log_file *file, log_filter *filter, enum sorting_order sort_by);
+int logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, enum sorting_order sort_by);
 
 #ifdef __cplusplus
 }

diff --git a/src/logger/logger.c b/src/logger/logger.c
index 434a351..1039ae9 100644 (file)
--- a/src/logger/logger.c
+++ b/src/logger/logger.c
@@ -646,8 +646,11 @@ static int reader_print_out_single_log(struct reader *reader, const struct logge
        assert(reader->buf_ptr);
        assert(logger_entry);
 
+       if (!log_should_print_line(reader->filter, logger_entry))
+               return 0;
+
        if (reader->file.path) {
-               logfile_write_with_rotation(logger_entry, &reader->file, reader->filter, reader->buf_ptr->sort_by);
+               logfile_write_with_rotation(logger_entry, &reader->file, reader->buf_ptr->sort_by);
                return 0;
        }
 
@@ -655,9 +658,6 @@ static int reader_print_out_single_log(struct reader *reader, const struct logge
        if (!strlen(tag))
                return 0;
 
-       if (!log_should_print_line(reader->filter, logger_entry))
-               return 0;
-
        int r = write(reader->file.path ? reader->file.fd : reader->fd_entity.fd, logger_entry, logger_entry->len);
        if (r < 0) {
                if (errno == EPIPE)
@@ -815,7 +815,10 @@ int service_reader_file(struct reader* reader)
                        parse_androidlogger_message((struct android_logger_entry *) buffer, &entry.header, r);
                        add_recv_timestamp(&entry.header);
 
-                       logfile_write_with_rotation(&entry.header, &reader->file, reader->filter, SORT_SENT_REAL);
+                       if (!log_should_print_line(reader->filter, &entry.header))
+                               return 0;
+
+                       logfile_write_with_rotation(&entry.header, &reader->file, SORT_SENT_REAL);
                }
        }
 

diff --git a/src/logutil/fd_info.c b/src/logutil/fd_info.c
index 0911380..6437490 100644 (file)
--- a/src/logutil/fd_info.c
+++ b/src/logutil/fd_info.c
@@ -85,6 +85,11 @@ int fdi_push_log(struct fd_info *fdi, struct sort_vector *logs, struct log_file
        if (!temp)
                return -ENOMEM;
 
+       if (!log_should_print_line(filter, temp)) {
+               free(temp);
+               return 0;
+       }
+
        if (IS_VECTOR_SIZE_SORTABLE(logs->size)) {
                struct timespec ts;
                extract_timestamp(temp, logs->sort_by, &ts);
@@ -93,11 +98,11 @@ int fdi_push_log(struct fd_info *fdi, struct sort_vector *logs, struct log_file
                if (ts.tv_sec > logs->start.tv_sec || (ts.tv_sec == logs->start.tv_sec && ts.tv_nsec > logs->start.tv_nsec))
                        logs->old_logs_dumped = true;
 
-               const int r = sort_vector_push(logs, temp, l_file, filter);
+               const int r = sort_vector_push(logs, temp, l_file);
                if (r)
                        return r;
        } else {
-               logfile_write_with_rotation(temp, l_file, filter, logs->sort_by);
+               logfile_write_with_rotation(temp, l_file, logs->sort_by);
                free(temp);
        }
 

diff --git a/src/logutil/logutil.c b/src/logutil/logutil.c
index cfd0ef9..ca8ede1 100644 (file)
--- a/src/logutil/logutil.c
+++ b/src/logutil/logutil.c
@@ -61,7 +61,7 @@ typedef enum action_e {
  * @param[in] timeout Sort timeout in ms
  * @return 1 if the log was old enough, else 0
  */
-int process_log(const struct logger_entry *e, struct timespec reference_ts, enum sorting_order stamp_type, struct log_file *l_file, log_filter *filter, long timeout)
+int process_log(const struct logger_entry *e, struct timespec reference_ts, enum sorting_order stamp_type, struct log_file *l_file, long timeout)
 {
        assert(e);
        assert(l_file);
@@ -77,18 +77,18 @@ int process_log(const struct logger_entry *e, struct timespec reference_ts, enum
        }
 
        if (timeout <= (s*1000 + ns/1000000)) {
-               logfile_write_with_rotation(e, l_file, filter, stamp_type);
+               logfile_write_with_rotation(e, l_file, stamp_type);
                return 1;
        } else
                return 0;
 }
 
-void flush_logs(struct sort_vector *logs, struct log_file *l_file, log_filter *filter)
+void flush_logs(struct sort_vector *logs, struct log_file *l_file)
 {
        struct timespec ts;
        clock_gettime(get_proper_clock(logs->sort_by), &ts);
 
-       while (!sort_vector_empty(logs) && process_log(sort_vector_back(logs), ts, logs->sort_by, l_file, filter, logs->timeout))
+       while (!sort_vector_empty(logs) && process_log(sort_vector_back(logs), ts, logs->sort_by, l_file, logs->timeout))
                sort_vector_pop(logs);
 }
 
@@ -228,7 +228,7 @@ static void do_print(struct fd_info **data_fds, int fd_count, struct sort_vector
                        goto cleanup;
 
                if (logs->dump == DUMP_CONTINUOUS && (!nfds || (logs->old_logs_dumped == 1 && sort_vector_time_span(logs) > logs->timeout)))
-                       flush_logs(logs, l_file, filter);
+                       flush_logs(logs, l_file);
        }
 
        if (put_logs_into_vector(data_fds, fd_count, 0, logs, l_file, filter) < 0)
@@ -239,7 +239,7 @@ static void do_print(struct fd_info **data_fds, int fd_count, struct sort_vector
                        sort_vector_pop(logs);
 
        logs->timeout = 0;
-       flush_logs(logs, l_file, filter);
+       flush_logs(logs, l_file);
 
 cleanup:
        free(evs);

diff --git a/src/logutil/sort_vector.c b/src/logutil/sort_vector.c
index ebc4b3b..c3d32bd 100644 (file)
--- a/src/logutil/sort_vector.c
+++ b/src/logutil/sort_vector.c
@@ -115,7 +115,7 @@ int sort_vector_used_size(struct sort_vector *logs)
  * @param[in] logs Log sorting vector
  * @return 0 on success, -errno on failure
  */
-int sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct log_file *l_file, log_filter *filter)
+int sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct log_file *l_file)
 {
        assert(logs);
        assert(logs->data);
@@ -125,14 +125,9 @@ int sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct lo
 
        int i;
 
-       if (!log_should_print_line(filter, p)) {
-               free(p);
-               return -EPERM;
-       }
-
        if (sort_vector_full(logs)) {
                if (logs->dump == DUMP_CONTINUOUS || logs->dump == DUMP_INFINITE)
-                       logfile_write_with_rotation(sort_vector_back(logs), l_file, filter, logs->sort_by);
+                       logfile_write_with_rotation(sort_vector_back(logs), l_file, logs->sort_by);
                sort_vector_pop(logs);
        }
 

diff --git a/src/logutil/sort_vector.h b/src/logutil/sort_vector.h
index b29447e..47329b9 100644 (file)
--- a/src/logutil/sort_vector.h
+++ b/src/logutil/sort_vector.h
@@ -47,5 +47,5 @@ int sort_vector_full(struct sort_vector *logs);
 int sort_vector_used_size(struct sort_vector *logs);
 void sort_vector_pop(struct sort_vector *logs);
 void sort_vector_apply_config(struct sort_vector *logs, struct log_config *config);
-int sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct log_file *l_file, log_filter *filter);
+int sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct log_file *l_file);
 

diff --git a/src/shared/log_file.c b/src/shared/log_file.c
index 39f2731..4cf093d 100644 (file)
--- a/src/shared/log_file.c
+++ b/src/shared/log_file.c
@@ -218,10 +218,8 @@ static void logfile_add_timestamp(struct log_file *file, struct timespec ts)
  * @param[in] file The file to write to
  * @returns 0 if log was successfully written, else 1
  */
-int logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, log_filter *filter, enum sorting_order sort_by)
+int logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, enum sorting_order sort_by)
 {
-       if (!log_should_print_line(filter, e))
-               return 1;
        int written_bytes = 0;
 
        struct timespec ts;

diff --git a/src/tests/fd_info.c b/src/tests/fd_info.c
index f983e62..b75bf8a 100644 (file)
--- a/src/tests/fd_info.c
+++ b/src/tests/fd_info.c
@@ -36,22 +36,20 @@ int __wrap_close(int fd)
 
 static bool sv_pushed;
 static int sv_push_retval;
-int __wrap_sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct log_file *l_file, log_filter *filter)
+int __wrap_sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct log_file *l_file)
 {
        assert(p == (struct logger_entry *) 0xBADFEEL);
        assert(l_file == (struct log_file *) 0xDEFACED);
-       assert(filter == (log_filter *) 404);
 
        sv_pushed = true;
        return sv_push_retval;
 }
 
 static bool sv_flushed;
-int __wrap_logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, log_filter *filter, enum sorting_order sort_by)
+int __wrap_logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, enum sorting_order sort_by)
 {
        assert(e == (struct logger_entry *) 0xBADFEEL);
        assert(file == (struct log_file *) 0xDEFACED);
-       assert(filter == (log_filter *) 404);
 
        sv_flushed = true;
        return 0;
@@ -79,6 +77,13 @@ void test_destroy(struct fd_info *fdi)
        assert(fdi == expected_destroyee);
 }
 
+bool __wrap_log_should_print_line(log_filter *p_filter, const struct logger_entry *entry)
+{
+       assert(p_filter == (log_filter *)404);
+       assert(entry == (struct logger_entry *)0xBADFEEL);
+       return true;
+}
+
 int main()
 {
        struct fd_ops fops = {

diff --git a/src/tests/log_file.c b/src/tests/log_file.c
index f52e481..96b853a 100644 (file)
--- a/src/tests/log_file.c
+++ b/src/tests/log_file.c
@@ -101,12 +101,6 @@ int __wrap_fstat(int fd, struct stat *buf)
        return 0;
 }
 
-static bool should_print_line;
-bool __wrap_log_should_print_line(log_filter *p_filter, const struct logger_entry *entry)
-{
-       return should_print_line;
-}
-
 int main()
 {
        struct log_file lf;
@@ -169,25 +163,19 @@ int main()
        custom_memcpy = true;
        lf.prev_sec = 4444;
        lf.prev_nsec = 6666;
-       should_print_line = false;
-       assert(logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, NULL, SORT_SENT_MONO));
-       assert(lf.prev_sec == 4444);
-       assert(lf.prev_nsec == 6666);
-
-       should_print_line = true;
        log_print_log_line_ret = -1;
-       assert(logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, NULL, SORT_SENT_MONO));
+       assert(logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, SORT_SENT_MONO));
        assert(lf.prev_sec == 4444);
        assert(lf.prev_nsec == 6666);
 
        log_print_log_line_ret = 1;
        fail_snprintf = true;
-       assert(!logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, NULL, SORT_SENT_MONO));
+       assert(!logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, SORT_SENT_MONO));
        assert(lf.prev_sec == 3333);
        assert(lf.prev_nsec == 9999);
 
        fail_snprintf = false;
-       assert(!logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, NULL, SORT_SENT_MONO));
+       assert(!logfile_write_with_rotation((struct logger_entry *) 0xBA5EBALL, &lf, SORT_SENT_MONO));
        custom_memcpy = false;
 
        logfile_free(&lf);

diff --git a/src/tests/logutil.c b/src/tests/logutil.c
index e39c314..8aa130d 100644 (file)
--- a/src/tests/logutil.c
+++ b/src/tests/logutil.c
@@ -6,8 +6,8 @@
 #include "../logutil/sort_vector.h"
 #include "../logutil/fd_info.h"
 
-int process_log(const struct logger_entry *e, struct timespec reference_ts, enum sorting_order stamp_type, struct log_file *l_file, log_filter *filter, long timeout);
-void flush_logs(struct sort_vector *logs, struct log_file *l_file, log_filter *filter);
+int process_log(const struct logger_entry *e, struct timespec reference_ts, enum sorting_order stamp_type, struct log_file *l_file, long timeout);
+void flush_logs(struct sort_vector *logs, struct log_file *l_file);
 struct fd_info *find_earliest_log(struct fd_info **data_fds, int fd_count, enum sorting_order sort_by);
 int put_logs_into_vector(struct fd_info **data_fds, int fd_count, int nfds, struct sort_vector *logs, struct log_file *l_file, log_filter *filter);
 long sort_vector_time_span(struct sort_vector *logs);
@@ -16,10 +16,9 @@ void set_sorting(struct sort_vector *logs, struct log_format format, bool is_pip
 
 int written_logs = 0;
 bool free_entries = false;
-int __wrap_logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, log_filter *filter, enum sorting_order sort_by)
+int __wrap_logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, enum sorting_order sort_by)
 {
        assert(file == (struct log_file *)0xDDD);
-       assert(filter == (log_filter *)0xEEE);
 
        if (free_entries)
                free((void *)e); // We shouldn't do this due to const, but there's no easy way around
@@ -62,6 +61,7 @@ const struct logger_entry *test_peek_entry(const struct fd_info *fdi)
 int fdi_push_log_ret = 0;
 int __wrap_fdi_push_log(struct fd_info *fdi, struct sort_vector *logs, struct log_file *l_file, log_filter *filter)
 {
+       assert(filter == (log_filter *)0xEEE);
        if (fdi_push_log_ret != 0)
                return fdi_push_log_ret;
        struct logger_entry *ent = calloc(1, sizeof(struct logger_entry));
@@ -69,7 +69,7 @@ int __wrap_fdi_push_log(struct fd_info *fdi, struct sort_vector *logs, struct lo
        memcpy(ent, fdi->ops->peek_entry(fdi), sizeof(struct logger_entry));
        struct fdi_internal *ii = fdi->priv_data;
        ii->has_log = false;
-       return sort_vector_push(logs, ent, l_file, filter);
+       return sort_vector_push(logs, ent, l_file);
 }
 
 int main()
@@ -91,16 +91,16 @@ int main()
        };
 
        assert(process_log(&ent, ts, SORT_SENT_MONO,
-               (struct log_file *)0xDDD, (log_filter *)0xEEE, 1) == 1);
+               (struct log_file *)0xDDD, 1) == 1);
        assert(written_logs == 1);
        assert(process_log(&ent, ts, SORT_SENT_REAL,
-               (struct log_file *)0xDDD, (log_filter *)0xEEE, 1) == 1);
+               (struct log_file *)0xDDD, 1) == 1);
        assert(written_logs == 2);
        assert(process_log(&ent, ts, SORT_RECV_MONO,
-               (struct log_file *)0xDDD, (log_filter *)0xEEE, 1) == 0);
+               (struct log_file *)0xDDD, 1) == 0);
        assert(written_logs == 2);
        assert(process_log(&ent, ts, SORT_RECV_REAL,
-               (struct log_file *)0xDDD, (log_filter *)0xEEE, 1) == 0);
+               (struct log_file *)0xDDD, 1) == 0);
        assert(written_logs == 2);
 
        struct sort_vector sv;
@@ -110,7 +110,7 @@ int main()
        sort_vector_finalize(&sv);
        assert(sort_vector_time_span(&sv) == 0);
 
-       flush_logs(&sv, (struct log_file *)0xDDD, (log_filter *)0xEEE);
+       flush_logs(&sv, (struct log_file *)0xDDD);
        assert(written_logs == 2 && sort_vector_used_size(&sv) == 0);
 
        struct log_file fail_file;
@@ -120,19 +120,19 @@ int main()
                assert(ent2);
                ent2->sec_sent_mono = 1;
                ent2->nsec_sent_mono = (79 + i) * 10000000;
-               sort_vector_push(&sv, ent2, &fail_file, (log_filter *)0xEEE);
+               sort_vector_push(&sv, ent2, &fail_file);
        }
 
        assert(sort_vector_time_span(&sv) == 110);
 
-       flush_logs(&sv, (struct log_file *)0xDDD, (log_filter *)0xEEE);
+       flush_logs(&sv, (struct log_file *)0xDDD);
        assert(written_logs == 8 && sort_vector_used_size(&sv) == 4);
 
        struct logger_entry *ent3 = calloc(1, sizeof(struct logger_entry));
        assert(ent3);
        ent3->sec_sent_mono = 0;
        ent3->nsec_sent_mono = 999999999;
-       sort_vector_push(&sv, ent3, &fail_file, (log_filter *)0xEEE);
+       sort_vector_push(&sv, ent3, &fail_file);
        assert(sort_vector_time_span(&sv) == 900);
 
        struct fd_ops test_ops = {

diff --git a/src/tests/sort_vector.c b/src/tests/sort_vector.c
index 359ff6e..83e7029 100644 (file)
--- a/src/tests/sort_vector.c
+++ b/src/tests/sort_vector.c
@@ -6,9 +6,8 @@
 #include "../logutil/sort_vector.h"
 
 size_t total_flushed;
-int __wrap_logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, log_filter *filter, enum sorting_order sort_by)
+int __wrap_logfile_write_with_rotation(const struct logger_entry *e, struct log_file *file, enum sorting_order sort_by)
 {
-       assert(filter == (log_filter *)0xF1);
        total_flushed += (size_t) e;
        return 19;
 }
@@ -18,12 +17,6 @@ bool __wrap_log_entry_is_earlier(const enum sorting_order sort_by, const struct
        return lhs < rhs;
 }
 
-static bool should_print_line;
-bool __wrap_log_should_print_line(log_filter *p_filter, const struct logger_entry *entry)
-{
-       return should_print_line;
-}
-
 int __wrap_log_config_get_int(const struct log_config *config, const char *key, int default_val)
 {
        assert(config == (struct log_config *) 0xC0B0L);
@@ -76,12 +69,11 @@ int main()
        assert(sv.data);
 
        // sorting correctness checks
-       should_print_line = true;
        sv.dump = 0;
        struct log_file lf;
        memset(&lf, 0, sizeof(struct log_file));
 
-#define ADD(x) assert(!sort_vector_push(&sv, (struct logger_entry *) x, &lf, (log_filter *)0xF1))
+#define ADD(x) assert(!sort_vector_push(&sv, (struct logger_entry *) x, &lf))
 #define POP(x) \
        free_total = 0; \
        sort_vector_pop(&sv); \
@@ -156,12 +148,6 @@ int main()
        assert(sv.begin == 4);
        assert(sv.end == 3);
 
-       should_print_line = false;
-       free_total = 0;
-       assert(-EPERM == sort_vector_push(&sv, (struct logger_entry *) 9987, &lf, (log_filter *)0xF1));
-       assert(free_total == 9987);
-       should_print_line = true;
-
        struct logger_entry **const data = sv.data;
        free_total = 0;
        sort_vector_free(&sv);