From 08c5c45c1e8938b83bdbed87f2782b49c288ffa1 Mon Sep 17 00:00:00 2001 From: Maciej Slodczyk Date: Thu, 15 Feb 2018 13:29:46 +0100 Subject: [PATCH] dlogutil: add pid and tid based filtering Add dlogutil command line options to specify pid and tid list to be passed to daemon and filter log output by. Change-Id: Icf233d8e01fec32a25ca2ec28791bf4e7642222f Signed-off-by: Maciej Slodczyk --- include/logprint.h | 36 ++++++++- src/logger/logger.c | 5 +- src/logutil/logutil.c | 18 +++++ src/logutil/logutil_doc.h | 2 + src/logutil/sort_vector.c | 2 +- src/shared/log_file.c | 2 +- src/shared/logprint.c | 185 ++++++++++++++++++++++++++++++++++++---------- src/tests/filters.c | 133 +++++++++++++++++++++++++++++++-- 8 files changed, 331 insertions(+), 52 deletions(-) diff --git a/include/logprint.h b/include/logprint.h index 31c4155..b5bc882 100644 --- a/include/logprint.h +++ b/include/logprint.h @@ -100,12 +100,42 @@ int log_add_filter_rule(log_format *p_format, const char *filterExpression); int log_add_filter_string(log_format *p_format, const char *filterString); + +/** + * pid: an int with a pid of a log source process, + * can be added multiple times with different values + * (in that case log_should_print_line() will logically + * OR all filter pid values to make a decision) + * + * returns 0 on success and -1 on invalid expression + * + * Assumes single threaded execution + * + */ + +int log_add_filter_pid(log_format *p_format, pid_t pid); + + +/** + * tid: an int with a tid of a log source thread, + * can be added multiple times with different values + * (in that case log_should_print_line() will logically + * OR all filter tid values to make a decision) + * + * returns 0 on success and -1 on invalid expression + * + * Assumes single threaded execution + * + */ + +int log_add_filter_tid(log_format *p_format, pthread_t tid); + /** - * returns true if this log line should be printed based on its priority - * and tag, and false if it should not + * returns true if this log line should be printed based on its entry + * data (priority, tag, pid and tid), and false if it should not */ bool log_should_print_line( - log_format *p_format, const char *tag, log_priority pri); + log_format *p_format, log_entry *entry); /** * Splits a wire-format buffer into an log_entry diff --git a/src/logger/logger.c b/src/logger/logger.c index fc9003f..d140e16 100755 --- a/src/logger/logger.c +++ b/src/logger/logger.c @@ -872,6 +872,7 @@ static int print_out_logs(struct logger *server, struct reader *reader) char tmp[LOG_MAX_SIZE]; char * tag; unsigned from = reader->current; + log_entry entry; int plaintext = reader->file.path && buf_writes_to_plaintext(reader->buf_ptr->id); @@ -911,13 +912,11 @@ static int print_out_logs(struct logger *server, struct reader *reader) continue; } - log_priority priority = log_priority_from_char(ple->msg[0]); - tag = ple->msg + 1; if (!strlen(tag)) continue; - if (!log_should_print_line(reader->file.format, tag, priority)) + if (log_process_log_buffer(ple, &entry) || !log_should_print_line(reader->file.format, &entry)) continue; r = write(reader->file.path ? reader->file.fd : reader->fd_entity.fd, ple, ple->len); diff --git a/src/logutil/logutil.c b/src/logutil/logutil.c index 3e05c02..bc83a4a 100755 --- a/src/logutil/logutil.c +++ b/src/logutil/logutil.c @@ -199,6 +199,8 @@ int parse_options(int argc, char **argv, struct log_file *l_file, struct sort_ve while (1) { static const struct option long_options[] = { {"dumpfile", required_argument, 0, 0}, + {"tid", required_argument, 0, 1}, + {"pid", required_argument, 0, 2}, {"help", no_argument, 0, 'h'}, {0, 0, 0, 0} }; @@ -212,6 +214,22 @@ int parse_options(int argc, char **argv, struct log_file *l_file, struct sort_ve case 0: list_add(file_input_names, optarg); break; + case 1: { /* tid filter */ + int tid; + if (sscanf(optarg, "%d", &tid) == 1) + log_add_filter_tid(l_file->format, tid); + else + err_arg_nondigit = 1; + break; + } + case 2: { /* pid filter */ + int pid; + if (sscanf(optarg, "%d", &pid) == 1) + log_add_filter_pid(l_file->format, pid); + else + err_arg_nondigit = 1; + break; + } case 'd': *dump = -1; break; diff --git a/src/logutil/logutil_doc.h b/src/logutil/logutil_doc.h index 99da685..1065f78 100644 --- a/src/logutil/logutil_doc.h +++ b/src/logutil/logutil_doc.h @@ -56,6 +56,8 @@ static void show_help(const char *cmd) " the default set is main + system + apps\n" " -u Sets the initial size of sort buffer (0 to disable sorting)\n" " Smaller is faster but lowers sorting quality\n" + " --pid Filter messages by process id\n" + " --tid Filter messages by thread id\n" " -h or --help show this help\n" " --dumpfile only for pipe backend. Parses a dlog_logger daemon generated file\n" "filterspecs are a series of\n[*][:priority]\n and \n*[:=priority]\n" diff --git a/src/logutil/sort_vector.c b/src/logutil/sort_vector.c index 53e298a..42b3dec 100644 --- a/src/logutil/sort_vector.c +++ b/src/logutil/sort_vector.c @@ -129,7 +129,7 @@ int sort_vector_push(struct sort_vector *logs, struct logger_entry *p, struct lo log_entry entry; if (log_process_log_buffer(p, &entry) || - !log_should_print_line(l_file->format, entry.tag, entry.priority)) { + !log_should_print_line(l_file->format, &entry)) { free(p); return -EPERM; } diff --git a/src/shared/log_file.c b/src/shared/log_file.c index 17f6761..be89979 100644 --- a/src/shared/log_file.c +++ b/src/shared/log_file.c @@ -219,7 +219,7 @@ void logfile_do_rotate(struct log_file *file) int logfile_write_with_rotation(struct logger_entry *e, struct log_file *file) { log_entry entry; - if (log_process_log_buffer(e, &entry) || !log_should_print_line(file->format, entry.tag, entry.priority)) + if (log_process_log_buffer(e, &entry) || !log_should_print_line(file->format, &entry)) return 1; int written_bytes = log_print_log_line(file->format, file->fd, &entry); if (written_bytes <= 0) diff --git a/src/shared/logprint.c b/src/shared/logprint.c index dbfdf59..72e6a79 100644 --- a/src/shared/logprint.c +++ b/src/shared/logprint.c @@ -16,6 +16,7 @@ * limitations under the License. */ +#include #include #include #include @@ -28,13 +29,29 @@ * @{ */ +#define FILTERINFO_PID_NONE -1 +#define FILTERINFO_TID_NONE -1 + +struct tag_and_prio { + char *tag; + int tagLength; + log_priority pri; + bool exactPri; + bool prefix; +}; + typedef struct FilterInfo_t { - char *mTag; - int mTagLength; + enum { + FILTER_TAG_AND_PRIO, + FILTER_PID, + FILTER_TID, + } type; + union { + struct tag_and_prio tnp; + pid_t pid; + pthread_t tid; + }; struct FilterInfo_t *p_next; - log_priority mPri; - bool mExactPri; - bool mPrefix; } FilterInfo; struct log_format_t { @@ -42,7 +59,6 @@ struct log_format_t { log_print_format format; log_priority global_pri; bool exact_global_pri; - }; /** @@ -55,27 +71,53 @@ struct log_format_t { * @return The new structure (or NULL if allocation failed). * @see filterinfo_free */ -static FilterInfo * filterinfo_new(const char *tag, log_priority pri, bool prefix, bool exactPri) +static FilterInfo *filterinfo_new(const char *tag, log_priority pri, bool prefix, bool exactPri, pid_t pid, pthread_t tid) { FilterInfo *p_ret = (FilterInfo *)calloc(1, sizeof(FilterInfo)); if (!p_ret) return NULL; - p_ret->mTag = strdup(tag); - - if (!p_ret->mTag) { - free(p_ret); - return NULL; + if (tag) { + p_ret->type = FILTER_TAG_AND_PRIO; + p_ret->tnp.tag = strdup(tag); + if (!p_ret->tnp.tag) { + free(p_ret); + return NULL; + } + p_ret->tnp.tagLength = strlen(p_ret->tnp.tag); + p_ret->tnp.pri = pri; + p_ret->tnp.exactPri = exactPri; + p_ret->tnp.prefix = prefix; + } else if (pid != FILTERINFO_PID_NONE) { + p_ret->type = FILTER_PID; + p_ret->pid = pid; + } else if (tid != FILTERINFO_TID_NONE) { + p_ret->type = FILTER_TID; + p_ret->tid = tid; + } else { + assert(false); } - p_ret->mTagLength = strlen(p_ret->mTag); - p_ret->mPri = pri; - p_ret->mExactPri = exactPri; - p_ret->mPrefix = prefix; - return p_ret; } +static FilterInfo *filterinfo_clone(FilterInfo *p_info) +{ + assert(p_info); + + switch (p_info->type) { + case FILTER_TAG_AND_PRIO: + return filterinfo_new(p_info->tnp.tag, p_info->tnp.pri, p_info->tnp.exactPri, p_info->tnp.prefix, FILTERINFO_PID_NONE, FILTERINFO_TID_NONE); + case FILTER_PID: + return filterinfo_new(NULL, 0, false, false, p_info->pid, FILTERINFO_TID_NONE); + case FILTER_TID: + return filterinfo_new(NULL, 0, false, false, FILTERINFO_PID_NONE, p_info->tid); + default: + assert(false); + return NULL; + } +} + /** * @brief Deallocate filter info * @details Deallocates the entire filter info structure @@ -87,8 +129,11 @@ static void filterinfo_free(FilterInfo *p_info) if (p_info == NULL) return; - free(p_info->mTag); - p_info->mTag = NULL; + if (p_info->type == FILTER_TAG_AND_PRIO) { + free(p_info->tnp.tag); + p_info->tnp.tag = NULL; + } + free(p_info); } @@ -168,37 +213,55 @@ char filter_pri_to_char(log_priority pri) * @brief Filter a line * @details Passes a line through filters to discover whether it should be logged or not * @param[in] p_format The format to work with - * @param[in] tag The line's tag - * @param[in] pri The line's priority - * @return true if the line should be printed, else false + * @param[in] entry The log entry to filter + * @return True if the line should be printed, else false */ -bool log_should_print_line(log_format *p_format, const char *tag, log_priority pri) +bool log_should_print_line(log_format *p_format, log_entry *entry) { + assert(p_format); + assert(entry); + FilterInfo *p_curFilter; bool prefix; bool matched = false; - for (p_curFilter = p_format->filters; p_curFilter != NULL; p_curFilter = p_curFilter->p_next) { - prefix = p_curFilter->mPrefix; - if ((prefix && (0 == strncmp(tag, p_curFilter->mTag, p_curFilter->mTagLength))) || - (!prefix && (0 == strcmp(tag, p_curFilter->mTag)))) { - matched = true; - if (p_curFilter->mExactPri) { - if (pri == p_curFilter->mPri) - return true; - } else { - if (pri >= p_curFilter->mPri) - return true; + switch (p_curFilter->type) { + case FILTER_TAG_AND_PRIO: + prefix = p_curFilter->tnp.prefix; + if ((prefix && (0 == strncmp(entry->tag, p_curFilter->tnp.tag, p_curFilter->tnp.tagLength))) || + (!prefix && (0 == strcmp(entry->tag, p_curFilter->tnp.tag)))) { + matched = true; + if (p_curFilter->tnp.exactPri) { + if (entry->priority == p_curFilter->tnp.pri) + return true; + } else { + if (entry->priority >= p_curFilter->tnp.pri) + return true; + } } + break; + case FILTER_PID: + matched = true; + if (entry->pid == p_curFilter->pid) + return true; + break; + case FILTER_TID: + matched = true; + if (entry->tid == p_curFilter->tid) + return true; + break; + default: + assert(false); } + } if (matched) return false; if (p_format->exact_global_pri) - return (pri == p_format->global_pri); + return (entry->priority == p_format->global_pri); else - return (pri >= p_format->global_pri); + return (entry->priority >= p_format->global_pri); } /** @@ -242,8 +305,8 @@ log_format *log_format_from_format(log_format *p_format) p_info = p_format->filters; while (p_info != NULL) { - FilterInfo *p_tmp; - p_tmp = filterinfo_new(p_info->mTag, p_info->mPri, p_info->mExactPri, p_info->mPrefix); + FilterInfo *p_tmp = filterinfo_clone(p_info); + if (!p_tmp) { log_format_free(p_ret); return NULL; @@ -391,7 +454,7 @@ int log_add_filter_rule(log_format *p_format, if (!tagName) goto error; - FilterInfo *p_fi = filterinfo_new(tagName, pri, pattern, exact); + FilterInfo *p_fi = filterinfo_new(tagName, pri, pattern, exact, FILTERINFO_PID_NONE, FILTERINFO_TID_NONE); free(tagName); if (!p_fi) goto error; @@ -442,6 +505,50 @@ error: } /** + * @brief Add pid to filter by + * @details Adds a single pid filtering rule + * @param[in] p_format The log format to add the filter rules to + * @param[in] pid A pid to filter by + * @return 0 on success, else -ENOMEM + * @remarks Assumes single threaded execution + */ +int log_add_filter_pid(log_format *p_format, pid_t pid) +{ + assert(p_format); + + FilterInfo *p_fi = filterinfo_new(NULL, 0, false, false, pid, FILTERINFO_TID_NONE); + if (!p_fi) + return -ENOMEM; + + p_fi->p_next = p_format->filters; + p_format->filters = p_fi; + + return 0; +} + +/** + * @brief Add tid to filter by + * @details Adds a single tid filtering rule + * @param[in] p_format The log format to add the filter rules to + * @param[in] pid A tid to filter by + * @return 0 on success, else -ENOMEM + * @remarks Assumes single threaded execution + */ +int log_add_filter_tid(log_format *p_format, pthread_t tid) +{ + assert(p_format); + + FilterInfo *p_fi = filterinfo_new(NULL, 0, false, false, FILTERINFO_PID_NONE, tid); + if (!p_fi) + return -ENOMEM; + + p_fi->p_next = p_format->filters; + p_format->filters = p_fi; + + return 0; +} + +/** * @brief Preprocess a log buffer for printing * @details Converts a log entry into a printable format * @param[in] entry_raw The raw entry to convert diff --git a/src/tests/filters.c b/src/tests/filters.c index 768a847..b6d182f 100644 --- a/src/tests/filters.c +++ b/src/tests/filters.c @@ -12,6 +12,98 @@ enum { fatal = (1 << 5), }; +int pid_tid_filter_list[] = { + 1234, + 2345, + 34567, + 98273545, + 1, +}; + +/** + * @brief Checks if a log message with a tid is printed as expected + * @details Verify the log_should_print_line function returns the expected value + * @param[in] line The number of source code line in this file, printed in debug messages + * @param[in] p_format The format to work with + * @param[in] tid The tid to filter with + * @param[in] expected The expected result returned by log_should_print_line function + * @return 0 if the log_should_print_line returns the expected result, 1 otherwise + */ +int check_print_line_tid_single(int line, log_format *p_format, pthread_t tid, bool expected) +{ + log_entry entry; + + entry.tag = NULL; + entry.pid = 0; + entry.tid = tid; + entry.priority = DLOG_DEBUG; // for unmatched entries that have to face the global filter + if (expected != log_should_print_line(p_format, &entry)) { + printf("Check in line %d for tid %lu failed to return %d \n", line, tid, + expected); + return 1; + } + return 0; +} + +/** + * @brief Checks if a log message if filtered properly for a group of tids + * @details Verify the log_should_print_line function returns the expected values + * @param[in] line The number of line in test, printed in debug messages + * @param[in] p_format The format to work with + * @param[in] tid The tid to filter with + * @return Number of tids for which log_should_print_line returns wrong answer + */ + +int check_print_line_tid(int line, log_format *p_format, pthread_t tid) +{ + int result = 0; + for (int tid_no = 0; tid_no < NELEMS(pid_tid_filter_list); tid_no++) + result += check_print_line_tid_single(line, p_format, pid_tid_filter_list[tid_no], (pid_tid_filter_list[tid_no] == tid)); + return result; +} + +/** + * @brief Checks if a log message with a pid is printed as expected + * @details Verify the log_should_print_line function returns the expected value + * @param[in] line The number of source code line in this file, printed in debug messages + * @param[in] p_format The format to work with + * @param[in] pid The pid to filter with + * @param[in] expected The expected result returned by log_should_print_line function + * @return 0 if the log_should_print_line returns the expected result, 1 otherwise + */ +int check_print_line_pid_single(int line, log_format *p_format, pid_t pid, bool expected) +{ + log_entry entry; + + entry.tag = NULL; + entry.tid = 0; + entry.pid = pid; + entry.priority = DLOG_DEBUG; // for unmatched entries that have to face the global filter + if (expected != log_should_print_line(p_format, &entry)) { + printf("Check in line %d for pid %d failed to return %d \n", line, pid, + expected); + return 1; + } + return 0; +} + +/** + * @brief Checks if a log message if filtered properly for a group of pids + * @details Verify the log_should_print_line function returns the expected values + * @param[in] line The number of line in test, printed in debug messages + * @param[in] p_format The format to work with + * @param[in] pid The pid to filter with + * @return Number of pids for which log_should_print_line returns wrong answer + */ + +int check_print_line_pid(int line, log_format *p_format, pid_t pid) +{ + int result = 0; + for (int pid_no = 0; pid_no < NELEMS(pid_tid_filter_list); pid_no++) + result += check_print_line_pid_single(line, p_format, pid_tid_filter_list[pid_no], (pid_tid_filter_list[pid_no] == pid)); + return result; +} + /** * @brief Checks if a log message with a tag and priority is printed as expected * @details Verify the log_should_print_line function returns the expected value @@ -22,9 +114,15 @@ enum { * @param[in] expected The expected result returned by log_should_print_line function * @return 0 if the log_should_print_line returns the expected result, 1 otherwise */ -int check_print_line_tag_prior(int line, log_format *p_format, const char *tag, int priority, bool expected) +int check_print_line_tag_prior(int line, log_format *p_format, char *tag, int priority, bool expected) { - if (expected != log_should_print_line(p_format, tag, priority)) { + log_entry entry; + + entry.tid = 0; + entry.pid = 0; + entry.tag = tag; + entry.priority = priority; + if (expected != log_should_print_line(p_format, &entry)) { printf("Check in line %d for tag %s and priority %c failed to return %d \n", line, tag, filter_pri_to_char(priority), expected); return 1; @@ -42,7 +140,7 @@ int check_print_line_tag_prior(int line, log_format *p_format, const char *tag, * @return Number of priorities for which log_should_print_line returns wrong answer */ -int check_print_line_tag(int line, log_format *p_format, const char *tag, int priors) +int check_print_line_tag(int line, log_format *p_format, char *tag, int priors) { int result = 0; result += check_print_line_tag_prior(line, p_format, tag, DLOG_VERBOSE, (priors & verbose) > 0); @@ -58,8 +156,9 @@ int main() { int err; int result = 0; - const char *tag, *tag_short, *tag_middle, *tag_long; + char *tag, *tag_short, *tag_middle, *tag_long; log_format *p_format; + log_entry entry; p_format = log_format_new(); @@ -112,7 +211,9 @@ int main() log_add_filter_rule(p_format, "crap:*"); - assert(log_should_print_line(p_format, "crap", DLOG_VERBOSE)); + entry.priority = DLOG_VERBOSE; + entry.tag = "crap"; + assert(log_should_print_line(p_format, &entry)); result += check_print_line_tag(__LINE__, p_format, "crap", verbose | debug | info | warn | error | fatal); result += check_print_line_tag(__LINE__, p_format, tag, verbose | debug | info | warn | error | fatal); result += check_print_line_tag(__LINE__, p_format, tag_short, info | warn | error | fatal); @@ -234,6 +335,28 @@ int main() result += check_print_line_tag(__LINE__, p_format, tag, 0); log_format_free(p_format); + //pid filtering rules + p_format = log_format_new(); + result += check_print_line_pid(__LINE__, p_format, 0); + err = log_add_filter_pid(p_format, 9876); + assert(err == 0); + result += check_print_line_pid(__LINE__, p_format, 9876); + err = log_add_filter_pid(p_format, pid_tid_filter_list[0]); + assert(err == 0); + result += check_print_line_pid(__LINE__, p_format, pid_tid_filter_list[0]); + log_format_free(p_format); + + //tid filtering rules + p_format = log_format_new(); + result += check_print_line_tid(__LINE__, p_format, 0); + err = log_add_filter_tid(p_format, 9876); + assert(err == 0); + result += check_print_line_tid(__LINE__, p_format, 9876); + err = log_add_filter_tid(p_format, pid_tid_filter_list[0]); + assert(err == 0); + result += check_print_line_tid(__LINE__, p_format, pid_tid_filter_list[0]); + log_format_free(p_format); + if (result > 0) exit(-1); return 0; -- 2.7.4