From 245a3c3d1b24b9e2a46a40acda9a166ff8e77d4a Mon Sep 17 00:00:00 2001 From: Timothy Stack Date: Fri, 10 Apr 2015 22:55:57 -0700 Subject: [PATCH] [fmt] allow timestamp to be specified in the log format Fixes #155 --- NEWS | 2 + docs/source/formats.rst | 6 +++ src/Makefile.am | 2 +- src/lnav_util.cc | 59 ++++++++++++------------------ src/lnav_util.hh | 4 +- src/log_format.cc | 6 +-- src/log_format.hh | 9 +++++ src/log_format_loader.cc | 8 +++- src/ptimec.hh | 57 ++++++++++++++++++++--------- src/ptimec_rt.cc | 49 +++++++++++++++++++++++++ test/formats/timestamp/format.json | 18 +++++++++ test/logfile_epoch.0 | 2 + test/test_date_time_scanner.cc | 10 +++++ test/test_json_format.sh | 2 +- test/test_logfile.sh | 8 ++++ 15 files changed, 179 insertions(+), 63 deletions(-) create mode 100644 test/formats/timestamp/format.json create mode 100644 test/logfile_epoch.0 diff --git a/NEWS b/NEWS index ebbe0eee..401f7abf 100644 --- a/NEWS +++ b/NEWS @@ -16,6 +16,8 @@ lnav v0.7.3: previous bookmarked line (e.g. error, warning, ...) * Added a 'zoom-to' command to change the zoom level of the histogram view. + * Log formats can now define their own timestamp formats with the + 'timestamp-format' field. Fixes: * Autotools scripts overhaul. diff --git a/docs/source/formats.rst b/docs/source/formats.rst index 66f3ae60..cc06bc46 100644 --- a/docs/source/formats.rst +++ b/docs/source/formats.rst @@ -73,6 +73,12 @@ fields: :timestamp-field: The name of the field that contains the log message timestamp. Defaults to "timestamp". + :timestamp-format: An array of timestamp formats using a subset of the + strftime conversion specification. The following conversions are + supported: %a, %b, %L, %M, %H, %I, %d, %e, %k, %l, %m, %p, %y, %Y, %S, %s, + %Z, %z. In addition, you can also use '%i' for milliseconds from the + epoch. + :level-field: The name of the regex capture group that contains the log message level. Defaults to "level". diff --git a/src/Makefile.am b/src/Makefile.am index e1cb6685..140b2e63 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -44,7 +44,7 @@ TIME_FORMATS = \ "%b %d %H:%M:%S" \ "%m/%d/%y %H:%M:%S" \ "%m/%d/%Y %I:%M:%S:%L %p %Z" \ - "%N/%e/%Y %l:%M:%S %p" \ + "%m/%e/%Y %l:%M:%S %p" \ "%m%d %H:%M:%S" \ "%H:%M:%S" \ "%M:%S" \ diff --git a/src/lnav_util.cc b/src/lnav_util.cc index adef7f03..9e65997a 100644 --- a/src/lnav_util.cc +++ b/src/lnav_util.cc @@ -310,7 +310,7 @@ struct tm *secs2tm(time_t *tim_p, struct tm *res) return (res); } -bool next_format(const char *fmt[], int &index, int &locked_index) +bool next_format(const char * const fmt[], int &index, int &locked_index) { bool retval = true; @@ -360,7 +360,7 @@ const char *std_time_fmt[] = { const char *date_time_scanner::scan(const char *time_dest, size_t time_len, - const char *time_fmt[], + const char * const time_fmt[], struct exttm *tm_out, struct timeval &tv_out) { @@ -433,46 +433,33 @@ const char *date_time_scanner::scan(const char *time_dest, break; } } - else if ((retval = strptime(time_dest, - time_fmt[curr_time_fmt], - &tm_out->et_tm)) != NULL) { - if (time_fmt[curr_time_fmt] == time_fmt_with_zone) { - int lpc; - - for (lpc = 0; retval[lpc] && retval[lpc] != ' '; lpc++) { + else { + off_t off = 0; + if (ptime_fmt(time_fmt[curr_time_fmt], tm_out, time_dest, off, time_len)) { + retval = &time_dest[off]; + if (tm_out->et_tm.tm_year < 70) { + tm_out->et_tm.tm_year = 80; } - if (retval[lpc] == ' ' && - sscanf(&retval[lpc], "%d", &tm_out->et_tm.tm_year) == 1) { - lpc += 1; - for (; retval[lpc] && isdigit(retval[lpc]); lpc++) { + if (this->dts_local_time) { + time_t gmt = tm2sec(&tm_out->et_tm); - } - retval = &retval[lpc]; - } - } - - if (tm_out->et_tm.tm_year < 70) { - tm_out->et_tm.tm_year = 80; - } - if (this->dts_local_time) { - time_t gmt = tm2sec(&tm_out->et_tm); - - localtime_r(&gmt, &tm_out->et_tm); + this->to_localtime(gmt, *tm_out); #ifdef HAVE_STRUCT_TM_TM_ZONE - tm_out->et_tm.tm_zone = NULL; + tm_out->et_tm.tm_zone = NULL; #endif - tm_out->et_tm.tm_isdst = 0; + tm_out->et_tm.tm_isdst = 0; + } + + tv_out.tv_sec = tm2sec(&tm_out->et_tm); + tv_out.tv_usec = tm_out->et_nsec / 1000; + + this->dts_fmt_lock = curr_time_fmt; + this->dts_fmt_len = retval - time_dest; + + found = true; + break; } - - tv_out.tv_sec = tm2sec(&tm_out->et_tm); - tv_out.tv_usec = tm_out->et_nsec / 1000; - - this->dts_fmt_lock = curr_time_fmt; - this->dts_fmt_len = retval - time_dest; - - found = true; - break; } } diff --git a/src/lnav_util.hh b/src/lnav_util.hh index bbcc20b0..b5ee579d 100644 --- a/src/lnav_util.hh +++ b/src/lnav_util.hh @@ -164,7 +164,7 @@ enum file_format_t { file_format_t detect_file_format(const std::string &filename); -bool next_format(const char *fmt[], int &index, int &locked_index); +bool next_format(const char * const fmt[], int &index, int &locked_index); inline bool is_glob(const char *fn) { @@ -250,7 +250,7 @@ struct date_time_scanner { const char *scan(const char *time_src, size_t time_len, - const char *time_fmt[], + const char * const time_fmt[], struct exttm *tm_out, struct timeval &tv_out); }; diff --git a/src/log_format.cc b/src/log_format.cc index b53575d7..fd35f162 100644 --- a/src/log_format.cc +++ b/src/log_format.cc @@ -664,7 +664,7 @@ bool external_log_format::scan(std::vector &dst, if ((last = this->lf_date_time.scan(ts_str, ts->length(), - NULL, + this->get_timestamp_formats(), &log_time_tm, log_tv)) == NULL) { continue; @@ -797,7 +797,7 @@ static int read_json_field(yajlpp_parse_context *ypc, const unsigned char *str, struct timeval tv_out; if (jlu->jlu_format->lf_timestamp_field == field_name) { - jlu->jlu_format->lf_date_time.scan((const char *)str, len, NULL, &tm_out, tv_out); + jlu->jlu_format->lf_date_time.scan((const char *)str, len, jlu->jlu_format->get_timestamp_formats(), &tm_out, tv_out); jlu->jlu_base_line->set_time(tv_out); } else if (jlu->jlu_format->elf_level_field == field_name) { @@ -1200,7 +1200,7 @@ void external_log_format::build(std::vector &errors) struct exttm tm; found = true; - if (ts_len == -1 || dts.scan(ts, ts_len, NULL, &tm, tv) == NULL) { + if (ts_len == -1 || dts.scan(ts, ts_len, this->get_timestamp_formats(), &tm, tv) == NULL) { errors.push_back("error:" + this->elf_name + ":invalid sample -- " + diff --git a/src/log_format.hh b/src/log_format.hh index 148214f6..cba48716 100644 --- a/src/log_format.hh +++ b/src/log_format.hh @@ -580,6 +580,14 @@ public: return retval; }; + const char * const *get_timestamp_formats() const { + if (this->lf_timestamp_format.empty()) { + return NULL; + } + + return &this->lf_timestamp_format[0]; + }; + void check_for_new_year(std::vector &dst, const struct timeval &log_tv); @@ -587,6 +595,7 @@ public: int lf_fmt_lock; intern_string_t lf_timestamp_field; int lf_timestamp_field_index; + std::vector lf_timestamp_format; std::map lf_action_defs; protected: static std::vector lf_root_formats; diff --git a/src/log_format_loader.cc b/src/log_format_loader.cc index 1b7d8ab1..5ed2ec74 100644 --- a/src/log_format_loader.cc +++ b/src/log_format_loader.cc @@ -148,6 +148,8 @@ static int read_format_field(yajlpp_parse_context *ypc, const unsigned char *str elf->lf_timestamp_field = intern_string::lookup(value); else if (field_name == "body-field") elf->elf_body_field = intern_string::lookup(value); + else if (field_name == "timestamp-format") + elf->lf_timestamp_format.push_back(intern_string::lookup(value)->get()); return 1; } @@ -371,10 +373,12 @@ static int read_json_variable_num(yajlpp_parse_context *ypc, long long val) static struct json_path_handler format_handlers[] = { json_path_handler("^/\\w+/regex/[^/]+/pattern$", read_format_regex), - json_path_handler("^/\\w+/(json|convert-to-local-time)$", read_format_bool), + json_path_handler("^/\\w+/(json|convert-to-local-time|epoch-timestamp)$", read_format_bool), json_path_handler("^/\\w+/timestamp-divisor$", read_format_double) .add_cb(read_format_int), - json_path_handler("^/\\w+/(file-pattern|level-field|timestamp-field|body-field|url|url#|title|description)$", + json_path_handler("^/\\w+/(file-pattern|level-field|timestamp-field|" + "body-field|url|url#|title|description|" + "timestamp-format#)$", read_format_field), json_path_handler("^/\\w+/level/" "(trace|debug\\d*|info|stats|warning|error|critical|fatal)$", diff --git a/src/ptimec.hh b/src/ptimec.hh index 404bdba7..ffeb6e3d 100644 --- a/src/ptimec.hh +++ b/src/ptimec.hh @@ -40,6 +40,8 @@ #include #include +struct tm *secs2tm(time_t *tim_p, struct tm *res); + enum exttm_bits_t { ETB_YEAR_SET, ETB_MONTH_SET, @@ -162,6 +164,21 @@ inline bool ptime_S(struct exttm *dst, const char *str, off_t &off_inout, ssize_ return (dst->et_tm.tm_sec >= 0 && dst->et_tm.tm_sec <= 59); } +inline bool ptime_s(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) +{ + time_t epoch = 0; + + while (off_inout < len && isdigit(str[off_inout])) { + epoch *= 10; + epoch += str[off_inout] - '0'; + off_inout += 1; + } + + secs2tm(&epoch, &dst->et_tm); + + return (epoch > 0); +} + inline bool ptime_L(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) { int ms = 0; @@ -210,6 +227,24 @@ inline bool ptime_H(struct exttm *dst, const char *str, off_t &off_inout, ssize_ return (dst->et_tm.tm_hour >= 0 && dst->et_tm.tm_hour <= 23); } +inline bool ptime_i(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) +{ + uint64_t epoch_ms = 0; + time_t epoch; + + while (off_inout < len && isdigit(str[off_inout])) { + epoch_ms *= 10; + epoch_ms += str[off_inout] - '0'; + off_inout += 1; + } + + dst->et_nsec = (epoch_ms % 1000ULL) * 1000000; + epoch = (epoch_ms / 1000ULL); + secs2tm(&epoch, &dst->et_tm); + + return (epoch_ms > 0); +} + inline bool ptime_I(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) { PTIME_CONSUME(2, { @@ -268,11 +303,11 @@ inline bool ptime_e(struct exttm *dst, const char *str, off_t &off_inout, ssize_ return false; } -inline bool ptime_N(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) +inline bool ptime_m(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) { dst->et_tm.tm_mon = 0; PTIME_CONSUME(1, { - if (str[off_inout] < '1' || str[off_inout] > '9') { + if (str[off_inout] < '0' || str[off_inout] > '9') { return false; } dst->et_tm.tm_mon = str[off_inout] - '0'; @@ -334,22 +369,6 @@ inline bool ptime_l(struct exttm *dst, const char *str, off_t &off_inout, ssize_ return (dst->et_tm.tm_hour >= 1 && dst->et_tm.tm_hour <= 12); } -inline bool ptime_m(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) -{ - PTIME_CONSUME(2, { - if (str[off_inout + 1] > '9') { - return false; - } - dst->et_tm.tm_mon = ((str[off_inout] - '0') * 10 + (str[off_inout + 1] - '0')) - 1; - }); - - if (0 <= dst->et_tm.tm_mon && dst->et_tm.tm_mon <= 11) { - dst->et_flags |= ETF_MONTH_SET; - return true; - } - return false; -} - inline bool ptime_p(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len) { PTIME_CONSUME(2, { @@ -483,6 +502,8 @@ inline bool ptime_char(char val, const char *str, off_t &off_inout, ssize_t len) typedef bool (*ptime_func)(struct exttm *dst, const char *str, off_t &off, ssize_t len); +bool ptime_fmt(const char *fmt, struct exttm *dst, const char *str, off_t &off, ssize_t len); + struct ptime_fmt { const char *pf_fmt; ptime_func pf_func; diff --git a/src/ptimec_rt.cc b/src/ptimec_rt.cc index ffaf45c4..e57d2369 100644 --- a/src/ptimec_rt.cc +++ b/src/ptimec_rt.cc @@ -52,3 +52,52 @@ bool ptime_b_slow(struct exttm *dst, const char *str, off_t &off_inout, ssize_t return false; } + +#define FMT_CASE(ch, c) \ + case ch: \ + if (!ptime_ ## c(dst, str, off, len)) return false; \ + lpc += 1; \ + break + +bool ptime_fmt(const char *fmt, struct exttm *dst, const char *str, off_t &off, ssize_t len) +{ + for (ssize_t lpc = 0; fmt[lpc]; lpc++) { + if (fmt[lpc] == '%') { + switch (fmt[lpc + 1]) { + case 'a': + case 'Z': + if (fmt[lpc + 2]) { + if (!ptime_upto(fmt[lpc + 2], str, off, len)) return false; + lpc += 2; + } + else { + if (!ptime_upto_end(str, off, len)) return false; + lpc += 1; + } + break; + FMT_CASE('b', b); + FMT_CASE('S', S); + FMT_CASE('s', s); + FMT_CASE('L', L); + FMT_CASE('M', M); + FMT_CASE('H', H); + FMT_CASE('i', i); + FMT_CASE('I', I); + FMT_CASE('d', d); + FMT_CASE('e', e); + FMT_CASE('k', k); + FMT_CASE('l', l); + FMT_CASE('m', m); + FMT_CASE('p', p); + FMT_CASE('Y', Y); + FMT_CASE('y', y); + FMT_CASE('z', z); + } + } + else { + if (!ptime_char(fmt[lpc], str, off, len)) return false; + } + } + + return true; +} \ No newline at end of file diff --git a/test/formats/timestamp/format.json b/test/formats/timestamp/format.json new file mode 100644 index 00000000..9cd476fb --- /dev/null +++ b/test/formats/timestamp/format.json @@ -0,0 +1,18 @@ +{ + "epoch_log": { + "title": "epoch timestamp test", + "regex": { + "std": { + "pattern": "^(?\\d+) (?.*)$" + } + }, + "timestamp-format" : [ + "%i" + ], + "sample": [ + { + "line": "1428634687123 Hello, World!" + } + ] + } +} diff --git a/test/logfile_epoch.0 b/test/logfile_epoch.0 new file mode 100644 index 00000000..2e0197f8 --- /dev/null +++ b/test/logfile_epoch.0 @@ -0,0 +1,2 @@ +1428634687123 Hello, World! +1428634687456 Goodbye, World! diff --git a/test/test_date_time_scanner.cc b/test/test_date_time_scanner.cc index 1045a4c0..0b480da4 100644 --- a/test/test_date_time_scanner.cc +++ b/test/test_date_time_scanner.cc @@ -73,4 +73,14 @@ int main(int argc, char *argv[]) assert(dts.scan(es_date, strlen(es_date), NULL, &es_tm, es_tv) != NULL); } } + + { + const char *epoch_str = "ts 1428721664 ]"; + struct exttm tm; + off_t off = 0; + + bool rc = ptime_fmt("ts %s ]", &tm, epoch_str, off, strlen(epoch_str)); + assert(rc); + assert(tm2sec(&tm.et_tm) == 1428721664); + } } diff --git a/test/test_json_format.sh b/test/test_json_format.sh index a2edbfda..ed41e38a 100644 --- a/test/test_json_format.sh +++ b/test/test_json_format.sh @@ -25,7 +25,7 @@ check_output "json log format is not working" <