[fmt] allow timestamp to be specified in the log format

Fixes #155

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.

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".
 

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" \

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++) {
-
-                }
-                if (retval[lpc] == ' ' &&
-                    sscanf(&retval[lpc], "%d", &tm_out->et_tm.tm_year) == 1) {
-                    lpc += 1;
-                    for (; retval[lpc] && isdigit(retval[lpc]); lpc++) {
+        else {
+            off_t off = 0;
 
-                    }
-                    retval = &retval[lpc];
+            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 (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);
+                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;
+                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;
+                this->dts_fmt_lock = curr_time_fmt;
+                this->dts_fmt_len  = retval - time_dest;
 
-            found = true;
-            break;
+                found = true;
+                break;
+            }
         }
     }
 

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);
 };

src/log_format.cc

@@ -664,7 +664,7 @@ bool external_log_format::scan(std::vector<logline> &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<std::string> &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 -- " +

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<logline> &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<const char *> lf_timestamp_format;
     std::map<std::string, action_def> lf_action_defs;
 protected:
     static std::vector<log_format *> lf_root_formats;

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)$",

src/ptimec.hh

@@ -40,6 +40,8 @@
 #include <sys/types.h>
 #include <arpa/inet.h>
 
+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;

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;
+}

test/formats/timestamp/format.json

@@ -0,0 +1,18 @@
+{
+    "epoch_log": {
+        "title": "epoch timestamp test",
+        "regex": {
+            "std": {
+                "pattern": "^(?<timestamp>\\d+) (?<body>.*)$"
+            }
+        },
+        "timestamp-format" : [
+            "%i"
+        ],
+        "sample": [
+            {
+                "line": "1428634687123 Hello, World!"
+            }
+        ]
+    }
+}

test/logfile_epoch.0

@@ -0,0 +1,2 @@
+1428634687123 Hello, World!
+1428634687456 Goodbye, World!

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);
+    }
 }

test/test_json_format.sh

@@ -25,7 +25,7 @@ check_output "json log format is not working" <<EOF
 EOF
 
 
-run_test ${lnav_test} -n -d /tmp/lnav.err \
+run_test ${lnav_test} -n \
     -I ${test_dir} \
     -c ';select * from test_log' \
     -c ':write-csv-to -' \

test/test_logfile.sh

@@ -113,6 +113,14 @@ Nov 03 08:09:33 2007 -- 816
 Nov 03 08:09:33 2007 -- 816
 EOF
 
+
+run_test ./drive_logfile -t -f epoch_log ${srcdir}/logfile_epoch.0
+
+check_output "epoch_log timestamp interpreted incorrectly?" <<EOF
+Apr 10 02:58:07 2015 -- 123
+Apr 10 02:58:07 2015 -- 456
+EOF
+
 ##
 
 run_test ./drive_logfile -v -f syslog_log ${srcdir}/logfile_syslog.0