[time] add support for TAI64N timestamps

Fixes #300

NEWS

@@ -38,6 +38,7 @@ lnav v0.8.1:
        executions.
      * Added a "/ui/clock-format" configuration option that controls the time
        format in the top-left corner.
+     * Added support for TAI64 timestamps (http://cr.yp.to/libtai/tai64.html).
 
      Interface Changes:
      * The 'o/O' hotkeys have been reassigned to navigate through log

src/Makefile.am

@@ -36,6 +36,7 @@ init-sql.c: bin2c
 	$(BIN2C_V)./bin2c -z -c $< $@
 
 TIME_FORMATS = \
+    "@%@" \
     "%Y-%m-%d %H:%M:%S" \
     "%Y-%m-%d %H:%M" \
     "%Y-%m-%dT%H:%M:%S.%f%z" \

src/lnav_util.cc

@@ -38,8 +38,6 @@
 #include <ctype.h>
 #include <wordexp.h>
 
-#include <sqlite3.h>
-
 #include <fstream>
 
 #include "auto_fd.hh"
@@ -226,12 +224,6 @@ std::string precise_time_ago(const struct timeval &tv, bool convert_local)
     }
 }
 
-/* XXX figure out how to do this with the template */
-void sqlite_close_wrapper(void *mem)
-{
-    sqlite3_close((sqlite3 *)mem);
-}
-
 std::string get_current_dir(void)
 {
     char        cwd[FILENAME_MAX];
@@ -561,7 +553,8 @@ const char *date_time_scanner::scan(const char *time_dest,
                 if (tm_out->et_tm.tm_year < 70) {
                     tm_out->et_tm.tm_year = 80;
                 }
-                if (convert_local && this->dts_local_time) {
+                if (convert_local &&
+                    (this->dts_local_time || tm_out->et_flags & ETF_EPOCH_TIME)) {
                     time_t gmt = tm2sec(&tm_out->et_tm);
 
                     this->to_localtime(gmt, *tm_out);
@@ -584,7 +577,8 @@ const char *date_time_scanner::scan(const char *time_dest,
                 if (tm_out->et_tm.tm_year < 70) {
                     tm_out->et_tm.tm_year = 80;
                 }
-                if (convert_local && this->dts_local_time) {
+                if (convert_local &&
+                    (this->dts_local_time || tm_out->et_flags & ETF_EPOCH_TIME)) {
                     time_t gmt = tm2sec(&tm_out->et_tm);
 
                     this->to_localtime(gmt, *tm_out);

src/lnav_util.hh

@@ -168,9 +168,6 @@ object_field_t<UnaryFunction, Member> object_field(UnaryFunction &func,
     return object_field_t<UnaryFunction, Member>(func, mem);
 }
 
-/* XXX figure out how to do this with the template */
-void sqlite_close_wrapper(void *mem);
-
 std::string get_current_dir(void);
 
 bool change_to_parent_dir(void);

src/log_format.cc

@@ -280,6 +280,7 @@ const char *log_format::log_scanf(const char *line,
 
             if (retval) {
                 this->lf_fmt_lock = curr_fmt;
+                this->lf_timestamp_flags = tm_out->et_flags;
                 done = true;
             }
         }
@@ -712,6 +713,7 @@ log_format::scan_result_t external_log_format::scan(std::vector<logline> &dst,
             continue;
         }
 
+        this->lf_timestamp_flags = log_time_tm.et_flags;
         if (level_cap != NULL && level_cap->c_begin != -1) {
             pcre_context_static<128> pc_level;
             pcre_input pi_level(pi.get_substr_start(level_cap),
@@ -979,6 +981,7 @@ static int read_json_field(yajlpp_parse_context *ypc, const unsigned char *str,
 
     if (jlu->jlu_format->lf_timestamp_field == field_name) {
         jlu->jlu_format->lf_date_time.scan((const char *)str, len, jlu->jlu_format->get_timestamp_formats(), &tm_out, tv_out);
+        jlu->jlu_format->lf_timestamp_flags = tm_out.et_flags;
         jlu->jlu_base_line->set_time(tv_out);
     }
     else if (jlu->jlu_format->elf_level_field == field_name) {

src/log_format.hh

@@ -669,7 +669,8 @@ public:
 
     log_format() : lf_mod_index(0),
                    lf_fmt_lock(-1),
-                   lf_timestamp_field(intern_string::lookup("timestamp", -1)) {
+                   lf_timestamp_field(intern_string::lookup("timestamp", -1)),
+                   lf_timestamp_flags(0) {
     };
 
     virtual ~log_format() { };
@@ -779,6 +780,7 @@ public:
     int lf_fmt_lock;
     intern_string_t lf_timestamp_field;
     std::vector<const char *> lf_timestamp_format;
+    int lf_timestamp_flags;
     std::map<std::string, action_def> lf_action_defs;
     std::vector<logline_value_stats> lf_value_stats;
 protected:

src/log_format_impls.cc

@@ -87,6 +87,7 @@ class generic_log_format : public log_format {
 
     static pcre_format *get_pcre_log_formats() {
         static pcre_format log_fmt[] = {
+            pcre_format("^(?<timestamp>@[0-9a-zA-Z]{16,24})(.*)"),
             pcre_format("^(?<timestamp>[\\dTZ: +/\\-,\\.-]+)([^:]+)"),
             pcre_format("^(?<timestamp>[\\w:+/\\.-]+) \\[\\w (.*)"),
             pcre_format("^(?<timestamp>[\\w:,/\\.-]+) (.*)"),

src/logfile_sub_source.cc

@@ -46,7 +46,6 @@ bookmark_type_t logfile_sub_source::BM_FILES("");
 logfile_sub_source::logfile_sub_source()
     : lss_flags(0),
       lss_token_file(NULL),
-      lss_token_date_end(0),
       lss_min_log_level(logline::LEVEL_UNKNOWN),
       lss_index_delegate(NULL),
       lss_longest_line(0)
@@ -118,54 +117,82 @@ void logfile_sub_source::text_value_for_line(textview_curses &tc,
         return;
     }
 
+    this->lss_token_attrs.clear();
+    this->lss_token_values.clear();
     this->lss_share_manager.invalidate_refs();
     this->lss_token_value =
         this->lss_token_file->read_line(this->lss_token_line);
 
-    this->lss_token_date_end = 0;
+    log_format *format = this->lss_token_file->get_format();
+
     value_out = this->lss_token_value;
     if (this->lss_flags & F_SCRUB) {
-        log_format *lf = this->lss_token_file->get_format();
-
-        lf->scrub(value_out);
+        format->scrub(value_out);
     }
 
-    if (this->lss_token_file->is_time_adjusted() &&
-        !this->lss_token_line->is_continued()) {
-        log_format *format = this->lss_token_file->get_format();
+    if (!this->lss_token_line->is_continued()) {
+        shared_buffer_ref sbr;
 
-        if (format->lf_date_time.dts_fmt_lock != -1) {
-            shared_buffer_ref sbr;
-            std::vector<logline_value> line_values;
-            struct timeval adjusted_time;
-            struct tm adjusted_tm;
-            string_attrs_t sa;
-            char buffer[128];
-            const char *fmt;
-
-            fmt = PTIMEC_FORMAT_STR[format->lf_date_time.dts_fmt_lock];
-            adjusted_time = this->lss_token_line->get_timeval();
-            strftime(buffer, sizeof(buffer),
-                     fmt,
-                     gmtime_r(&adjusted_time.tv_sec, &adjusted_tm));
-
-            sbr.share(this->lss_share_manager,
-                (char *)this->lss_token_value.c_str(), this->lss_token_value.size());
-            format->annotate(sbr, sa, line_values);
+        sbr.share(this->lss_share_manager,
+                  (char *)this->lss_token_value.c_str(), this->lss_token_value.size());
+        format->annotate(sbr, this->lss_token_attrs, this->lss_token_values);
 
+        if ((this->lss_token_file->is_time_adjusted() ||
+             format->lf_timestamp_flags & ETF_MACHINE_ORIENTED) &&
+            format->lf_date_time.dts_fmt_lock != -1) {
             struct line_range time_range;
 
-            time_range = find_string_attr_range(sa, &logline::L_TIMESTAMP);
-            if (time_range.lr_start != -1) {
+            time_range = find_string_attr_range(
+                this->lss_token_attrs, &logline::L_TIMESTAMP);
+            if (time_range.is_valid()) {
+                struct timeval adjusted_time;
+                struct tm adjusted_tm;
+                char buffer[128];
+                const char *fmt;
+
+                if (format->lf_timestamp_flags & ETF_MACHINE_ORIENTED) {
+                    format->lf_date_time.convert_to_timeval(
+                        &this->lss_token_value.c_str()[time_range.lr_start],
+                        time_range.length(),
+                        adjusted_time);
+                    fmt = "%Y-%m-%d %H:%M:%S.";
+                }
+                else {
+                    fmt = PTIMEC_FORMAT_STR[format->lf_date_time.dts_fmt_lock];
+                    adjusted_time = this->lss_token_line->get_timeval();
+                }
+                strftime(buffer, sizeof(buffer),
+                         fmt,
+                         gmtime_r(&adjusted_time.tv_sec, &adjusted_tm));
+
+                if (format->lf_timestamp_flags & ETF_MACHINE_ORIENTED) {
+                    size_t buffer_len = strlen(buffer);
+
+                    snprintf(&buffer[buffer_len], sizeof(buffer) - buffer_len,
+                             "%06d",
+                             adjusted_time.tv_usec);
+                }
+
                 const char *last = value_out.c_str();
-                int len = strlen(buffer);
+                ssize_t len = strlen(buffer);
 
                 if ((last[time_range.lr_start + len] == '.' ||
-                    last[time_range.lr_start + len] == ',') &&
+                     last[time_range.lr_start + len] == ',') &&
                     len + 4 <= time_range.length()) {
-                    snprintf(&buffer[len], sizeof(buffer) - len,
-                             ".%03d",
-                             this->lss_token_line->get_millis());
+                    len = snprintf(&buffer[len], sizeof(buffer) - len,
+                                   ".%03d",
+                                   this->lss_token_line->get_millis());
+                }
+
+                if (len > time_range.length()) {
+                    ssize_t padding = len - time_range.length();
+
+                    value_out.insert(time_range.lr_start,
+                                     padding,
+                                     ' ');
+                    shift_string_attrs(this->lss_token_attrs,
+                                       time_range.lr_start,
+                                       padding);
                 }
                 value_out.replace(time_range.lr_start,
                                   strlen(buffer),
@@ -213,7 +240,7 @@ void logfile_sub_source::text_attrs_for_line(textview_curses &lv,
     int time_offset_end = 0;
     int attrs           = 0;
 
-    value_out.clear();
+    value_out = this->lss_token_attrs;
     switch (this->lss_token_line->get_msg_level()) {
     case logline::LEVEL_FATAL:
     case logline::LEVEL_CRITICAL:
@@ -240,22 +267,13 @@ void logfile_sub_source::text_attrs_for_line(textview_curses &lv,
         attrs |= A_UNDERLINE;
     }
 
-    log_format *format = this->lss_token_file->get_format();
-    std::vector<logline_value> line_values;
-    
-    if (!this->lss_token_line->is_continued()) {
-        shared_buffer_ref sbr;
-
-        sbr.share(this->lss_share_manager,
-            (char *)this->lss_token_value.c_str(), this->lss_token_value.size());
-        format->annotate(sbr, value_out, line_values);
-    }
+    std::vector<logline_value> &line_values = this->lss_token_values;
 
     lr.lr_start = 0;
     lr.lr_end = this->lss_token_value.length();
     value_out.push_back(string_attr(lr, &textview_curses::SA_ORIGINAL_LINE));
 
-    lr.lr_start = time_offset_end + this->lss_token_date_end;
+    lr.lr_start = time_offset_end;
     lr.lr_end   = -1;
 
     value_out.push_back(string_attr(lr, &view_curses::VC_STYLE, attrs));
@@ -275,16 +293,7 @@ void logfile_sub_source::text_attrs_for_line(textview_curses &lv,
     }
 
     if (this->lss_files.size() > 1) {
-        for (string_attrs_t::iterator iter = value_out.begin();
-             iter != value_out.end();
-             ++iter) {
-            struct line_range *existing_lr = &iter->sa_range;
-
-            existing_lr->lr_start += 1;
-            if (existing_lr->lr_end != -1) {
-                existing_lr->lr_end += 1;
-            }
-        }
+        shift_string_attrs(value_out, 0, 1);
 
         lr.lr_start = 0;
         lr.lr_end = 1;

src/logfile_sub_source.hh

@@ -593,8 +593,9 @@ private:
 
     logfile *         lss_token_file;
     std::string       lss_token_value;
+    string_attrs_t    lss_token_attrs;
+    std::vector<logline_value> lss_token_values;
     shared_buffer     lss_share_manager;
-    int               lss_token_date_end;
     logfile::iterator lss_token_line;
     std::pair<int, size_t> lss_line_size_cache[LINE_SIZE_CACHE_SIZE];
     logline::level_t  lss_min_log_level;

src/ptimec.cc

@@ -78,6 +78,10 @@ int main(int argc, char *argv[])
                     }
                     arg += 1;
                     break;
+                case '@':
+                    printf("    if (!ptime_at(dst, str, off, len)) return false;\n");
+                    arg += 1;
+                    break;
                 default:
                     printf("    if (!ptime_%c(dst, str, off, len)) return false;\n",
                         arg[index + 1]);

src/ptimec.hh

@@ -46,12 +46,16 @@ enum exttm_bits_t {
     ETB_YEAR_SET,
     ETB_MONTH_SET,
     ETB_DAY_SET,
+    ETB_MACHINE_ORIENTED,
+    ETB_EPOCH_TIME,
 };
 
 enum exttm_flags_t {
     ETF_YEAR_SET = (1L << ETB_YEAR_SET),
     ETF_MONTH_SET = (1L << ETB_MONTH_SET),
     ETF_DAY_SET = (1L << ETB_DAY_SET),
+    ETF_MACHINE_ORIENTED = (1L << ETB_MACHINE_ORIENTED),
+    ETF_EPOCH_TIME = (1L << ETB_EPOCH_TIME),
 };
 
 struct exttm {
@@ -502,6 +506,61 @@ inline bool ptime_char(char val, const char *str, off_t &off_inout, ssize_t len)
     return true;
 }
 
+template<typename T>
+inline bool ptime_hex_to_quad(T &value_inout, const char quad)
+{
+    value_inout <<= 4;
+    if ('0' <= quad && quad <= '9') {
+        value_inout |= ((quad - '0') & 0x0f);
+    }
+    else if ('a' <= quad && quad <= 'f') {
+        value_inout |= 10 + ((quad - 'a') & 0x0f);
+    }
+    else if ('A' <= quad && quad <= 'F') {
+        value_inout |= 10 + ((quad - 'A') & 0x0f);
+    }
+    else {
+        return false;
+    }
+
+    return true;
+}
+
+inline bool ptime_at(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len)
+{
+    PTIME_CONSUME(16, {
+        int64_t secs = 0;
+
+        for (int lpc = 0; lpc < 16; lpc++) {
+            char quad = str[off_inout + lpc];
+
+            if (!ptime_hex_to_quad(secs, quad)) {
+                return false;
+            }
+        }
+        dst->et_nsec = 0;
+
+        time_t small_secs = secs - 4611686018427387914ULL;
+        secs2tm(&small_secs, &dst->et_tm);
+    });
+
+    if ((len - off_inout) == 8) {
+        PTIME_CONSUME(8, {
+            for (int lpc = 0; lpc < 8; lpc++) {
+                char quad = str[off_inout + lpc];
+
+                if (!ptime_hex_to_quad(dst->et_nsec, quad)) {
+                    return false;
+                }
+            }
+        });
+    }
+
+    dst->et_flags |= ETF_MACHINE_ORIENTED|ETF_EPOCH_TIME;
+
+    return true;
+}
+
 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);

src/ptimec_rt.cc

@@ -92,6 +92,7 @@ bool ptime_fmt(const char *fmt, struct exttm *dst, const char *str, off_t &off,
                 FMT_CASE('Y', Y);
                 FMT_CASE('y', y);
                 FMT_CASE('z', z);
+                FMT_CASE('@', at);
             }
         }
         else {

src/sql_util.cc

@@ -707,3 +707,9 @@ int guess_type_from_pcre(const string &pattern, const char **collator)
         return SQLITE3_TEXT;
     }
 }
+
+/* XXX figure out how to do this with the template */
+void sqlite_close_wrapper(void *mem)
+{
+    sqlite3_close((sqlite3 *)mem);
+}

src/sql_util.hh

@@ -84,4 +84,7 @@ void sql_execute_script(sqlite3 *db,
 
 int guess_type_from_pcre(const std::string &pattern, const char **collator);
 
+/* XXX figure out how to do this with the template */
+void sqlite_close_wrapper(void *mem);
+
 #endif

src/view_curses.hh

@@ -312,6 +312,20 @@ inline void remove_string_attr(string_attrs_t &sa, const struct line_range &lr)
     }
 }
 
+inline void shift_string_attrs(string_attrs_t &sa, int32_t start, int32_t amount)
+{
+    for (string_attrs_t::iterator iter = sa.begin(); iter != sa.end(); ++iter) {
+        struct line_range *existing_lr = &iter->sa_range;
+
+        if (existing_lr->lr_start >= start) {
+            existing_lr->lr_start += amount;
+        }
+        if (existing_lr->lr_end != -1 && start < existing_lr->lr_end) {
+            existing_lr->lr_end += amount;
+        }
+    }
+}
+
 /**
  * A line that has attributes.
  */

test/CMakeLists.txt

@@ -7,6 +7,14 @@ add_executable(test_reltime test_reltime.cc
         ../src/relative_time.cc
         ../src/pcrepp.cc
         ../src/lnav_log.cc)
+add_executable(test_date_time_scanner test_date_time_scanner.cc
+        ../src/lnav_util.cc
+        ../../lbuild/src/time_fmts.cc
+        ../src/ptimec_rt.cc
+        ../src/pcrepp.cc
+        ../src/lnav_log.cc
+        ../src/spookyhash/SpookyV2.cpp)
 link_directories(/opt/local/lib)
 target_link_libraries(test_pcrepp /opt/local/lib/libpcre.a)
 target_link_libraries(test_reltime /opt/local/lib/libpcre.a)
+target_link_libraries(test_date_time_scanner /opt/local/lib/libpcre.a)

test/Makefile.am

@@ -271,6 +271,7 @@ dist_noinst_DATA = \
 	logfile_syslog.2 \
 	logfile_syslog_with_access_log.0 \
 	logfile_syslog_with_mixed_times.0 \
+	logfile_tai64n.0 \
 	logfile_tcf.0 \
 	logfile_tcf.1 \
 	logfile_tcsh_history.0 \

test/logfile_tai64n.0

@@ -0,0 +1,10 @@
+@40000000433225833b6e1a8c tcpserver: status: 5/30
+@40000000433225833b6e2644 tcpserver: pid 26162 from 194.206.24.40
+@40000000433225840c85ba04 tcpserver: ok 26162 a.mx.jms1.net:209.114.200.128:25 :194.206.24.40::1521
+@40000000433225840c8f0cbc rblsmtpd: 194.206.24.40 pid 26162: 451 We do not accept mail from IP addresses without reverse DNS.
+@40000000433225852a9ada4c tcpserver: status: 6/30
+@40000000433225852a9ae604 tcpserver: pid 26163 from 193.123.2.227
+@40000000433225852aa997bc tcpserver: ok 26163 a.mx.jms1.net:209.114.200.128:25 pixelwww.pixelpower.com:193.123.2.227::4232
+@40000000433225852aa9a374 rblsmtpd: 193.123.2.227 pid 26163: 553 Sent mail to honeypot qmmycemglyiuq@delete.net on 2005-01-04
+@400000004332258538eae27c tcpserver: end 26163 status 0
+@400000004332258538eaea4c tcpserver: status: 5/30

test/test_date_time_scanner.cc

@@ -41,11 +41,27 @@ static const char *BAD_TIMES[] = {
     "2013-22-01 12:01:22",
     "2013-00-01 12:01:22",
 
+    "@4000000043",
+
     NULL
 };
 
 int main(int argc, char *argv[])
 {
+    {
+        date_time_scanner dts;
+        struct timeval tv;
+
+        dts.convert_to_timeval("@40000000433225833b6e1a8c", -1, tv);
+        assert(tv.tv_sec == 1127334665);
+        assert(tv.tv_usec == 997071);
+
+        memset(&tv, 0, sizeof(tv));
+        dts.convert_to_timeval("@4000000043322583", -1, tv);
+        assert(tv.tv_sec == 1127334665);
+        assert(tv.tv_usec == 0);
+    }
+
     for (int lpc = 0; BAD_TIMES[lpc]; lpc++) {
         date_time_scanner dts;
         struct timeval tv;

test/test_logfile.sh

@@ -115,6 +115,21 @@ Jul 20 22:59:29 2009 -- 000
 Jul 20 22:59:29 2009 -- 000
 EOF
 
+run_test ./drive_logfile -t -f generic_log ${srcdir}/logfile_tai64n.0
+
+check_output "tai64n timestamps interpreted incorrectly?" <<EOF
+Sep 22 03:31:05 2005 -- 997
+Sep 22 03:31:05 2005 -- 997
+Sep 22 03:31:06 2005 -- 210
+Sep 22 03:31:06 2005 -- 210
+Sep 22 03:31:07 2005 -- 714
+Sep 22 03:31:07 2005 -- 714
+Sep 22 03:31:07 2005 -- 715
+Sep 22 03:31:07 2005 -- 715
+Sep 22 03:31:07 2005 -- 954
+Sep 22 03:31:07 2005 -- 954
+EOF
+
 touch -t 200711030923 ${srcdir}/logfile_strace_log.0
 run_test ./drive_logfile -t -f strace_log ${srcdir}/logfile_strace_log.0