[logfile] include microseconds when converting timestamps

Mentioned in #1145 Also, fix the field hiding issue mentioned in #1146
1 year ago · f2a0c8f21c
parent add3982d2e
commit f2a0c8f21c
14 changed files with 145 additions and 98 deletions
--- a/src/base/attr_line.cc
+++ b/src/base/attr_line.cc
@ -411,7 +411,7 @@ attr_line_t::apply_hide()

    for (auto& sattr : sa) {
        if (sattr.sa_type == &SA_HIDDEN && sattr.sa_range.length() > 3) {
-            struct line_range& lr = sattr.sa_range;
+            auto& lr = sattr.sa_range;

            std::for_each(sa.begin(), sa.end(), [&](string_attr& attr) {
                if (attr.sa_type == &VC_STYLE && lr.contains(attr.sa_range)) {
--- a/src/formats/tcf_log.json
+++ b/src/formats/tcf_log.json
@ -9,7 +9,7 @@
        ],
        "regex": {
            "std": {
-                "pattern": "^TCF (?<timestamp>\\d{2}:\\d{2}.\\d{3}): (?:Server-Properties: (?:.*)|channel server|\\w+: (?<dir>--->|<---) (?<type>\\w)(?: (?<token>\\w+))?(?: (?<service>\\w+))?(?: (?<name>\\w+))?(?: (?<msg>.*))?(?: <eom>))(?<body>.*)$"
+                "pattern": "^TCF (?<timestamp>\\d{2}:\\d{2}.\\d{3,6}): (?:Server-Properties: (?:.*)|channel server|\\w+: (?<dir>--->|<---) (?<type>\\w)(?: (?<token>\\w+))?(?: (?<service>\\w+))?(?: (?<name>\\w+))?(?: (?<msg>.*))?(?: <eom>))(?<body>.*)$"
            }
        },
        "value": {
--- a/src/log_format.cc
+++ b/src/log_format.cc
@ -1097,8 +1097,25 @@ external_log_format::annotate(uint64_t line_number,

    line.erase_ansi();
    if (this->elf_type != elf_type_t::ELF_TYPE_TEXT) {
-        values = this->jlf_line_values;
-        sa = this->jlf_line_attrs;
+        if (this->jlf_cached_full) {
+            values = this->jlf_line_values;
+            sa = this->jlf_line_attrs;
+        } else {
+            values.lvv_sbr = this->jlf_line_values.lvv_sbr;
+            for (const auto& llv : this->jlf_line_values.lvv_values) {
+                if (this->jlf_cached_sub_range.contains(llv.lv_origin)) {
+                    values.lvv_values.emplace_back(llv);
+                    values.lvv_values.back().lv_origin.shift(
+                        this->jlf_cached_sub_range.lr_start,
+                        -this->jlf_cached_sub_range.lr_start);
+                }
+            }
+            for (const auto& attr : this->jlf_line_attrs) {
+                if (this->jlf_cached_sub_range.contains(attr.sa_range)) {
+                    sa.emplace_back(attr);
+                }
+            }
+        }
        return;
    }

@ -1273,21 +1290,18 @@ external_log_format::rewrite(exec_context& ec,
        } else {
            field_value = exec_res.unwrapErr().to_attr_line().get_string();
        }
-        auto adj_origin
-            = iter->origin_in_full_msg(value_out.c_str(), value_out.length());
-
-        value_out.erase(adj_origin.lr_start, adj_origin.length());
+        value_out.erase(iter->lv_origin.lr_start, iter->lv_origin.length());

        int32_t shift_amount
-            = ((int32_t) field_value.length()) - adj_origin.length();
-        value_out.insert(adj_origin.lr_start, field_value);
+            = ((int32_t) field_value.length()) - iter->lv_origin.length();
+        value_out.insert(iter->lv_origin.lr_start, field_value);
        for (shift_iter = values.lvv_values.begin();
             shift_iter != values.lvv_values.end();
             ++shift_iter)
        {
-            shift_iter->lv_origin.shift(adj_origin.lr_start, shift_amount);
+            shift_iter->lv_origin.shift(iter->lv_origin.lr_start, shift_amount);
        }
-        shift_string_attrs(sa, adj_origin.lr_start, shift_amount);
+        shift_string_attrs(sa, iter->lv_origin.lr_start, shift_amount);
    }
 }

@ -1528,8 +1542,6 @@ external_log_format::get_subline(const logline& ll,

                            lr.lr_start = this->jlf_cached_line.size();

-                            lv_iter->lv_meta.lvm_hidden
-                                = lv_iter->lv_meta.lvm_user_hidden;
                            if ((int) str.size() > jfe.jfe_max_width) {
                                switch (jfe.jfe_overflow) {
                                    case json_format_element::overflow_t::
@ -1595,7 +1607,7 @@ external_log_format::get_subline(const logline& ll,
                                    lr, logline::L_OPID.value());
                            }
                            lv_iter->lv_origin = lr;
-                            used_values[distance(
+                            used_values[std::distance(
                                this->jlf_line_values.lvv_values.begin(),
                                lv_iter)]
                                = true;
@ -1699,7 +1711,7 @@ external_log_format::get_subline(const logline& ll,
                    = intern_string::lookup("body", -1);
                auto& lv = this->jlf_line_values.lvv_values[lpc];

-                if (lv.lv_meta.lvm_hidden || used_values[lpc]
+                if (lv.lv_meta.is_hidden() || used_values[lpc]
                    || body_name == lv.lv_meta.lvm_name)
                {
                    continue;
@ -1709,7 +1721,8 @@ external_log_format::get_subline(const logline& ll,
                size_t curr_pos = 0, nl_pos, line_len = -1;

                lv.lv_sub_offset = sub_offset;
-                lv.lv_origin.lr_start = 2 + lv.lv_meta.lvm_name.size() + 2;
+                lv.lv_origin.lr_start = this->jlf_cached_line.size() + 2
+                    + lv.lv_meta.lvm_name.size() + 2;
                do {
                    nl_pos = str.find('\n', curr_pos);
                    if (nl_pos != std::string::npos) {
@ -1770,6 +1783,8 @@ external_log_format::get_subline(const logline& ll,
                  this->jlf_cached_line.data() + this_off,
                  next_off - this_off);
    }
+    this->jlf_cached_sub_range.lr_start = this_off;
+    this->jlf_cached_sub_range.lr_end = next_off;
    this->jlf_line_values.lvv_sbr = sbr;
 }

@ -2837,7 +2852,7 @@ external_log_format::value_line_count(const intern_string_t ist,
        return (this->jlf_hide_extra || !top_level) ? 0 : line_count;
    }

-    if (iter->second->vd_meta.lvm_hidden) {
+    if (iter->second->vd_meta.is_hidden()) {
        return 0;
    }

--- a/src/log_format_ext.hh
+++ b/src/log_format_ext.hh
@ -412,6 +412,7 @@ public:
    logline_value_vector jlf_line_values;

    off_t jlf_cached_offset{-1};
+    line_range jlf_cached_sub_range;
    bool jlf_cached_full{false};
    std::vector<off_t> jlf_line_offsets;
    std::vector<char> jlf_cached_line;
--- a/src/logfile_sub_source.cc
+++ b/src/logfile_sub_source.cc
@ -261,6 +261,20 @@ logfile_sub_source::text_value_for_line(textview_curses& tc,
            {
                adjusted_time = this->lss_token_line->get_timeval();
                fmt = "%Y-%m-%d %H:%M:%S.%f";
+                if (format->lf_timestamp_flags & ETF_MICROS_SET) {
+                    struct timeval actual_tv;
+                    struct exttm tm;
+                    if (format->lf_date_time.scan(
+                            this->lss_token_value.data() + time_range.lr_start,
+                            time_range.length(),
+                            format->get_timestamp_formats(),
+                            &tm,
+                            actual_tv,
+                            false))
+                    {
+                        adjusted_time.tv_usec = actual_tv.tv_usec;
+                    }
+                }
                gmtime_r(&adjusted_time.tv_sec, &adjusted_tm.et_tm);
                adjusted_tm.et_nsec
                    = std::chrono::duration_cast<std::chrono::nanoseconds>(
@ -413,13 +427,7 @@ logfile_sub_source::text_attrs_for_line(textview_curses& lv,
            continue;
        }

-        line_range ident_range = line_value.lv_origin;
-        if (this->lss_token_flags & RF_FULL) {
-            ident_range = line_value.origin_in_full_msg(
-                this->lss_token_value.c_str(), this->lss_token_value.length());
-        }
-
-        value_out.emplace_back(ident_range,
+        value_out.emplace_back(line_value.lv_origin,
                               VC_ROLE.value(role_t::VCR_IDENTIFIER));
    }

--- a/test/expected/test_json_format.sh_40223ac4742883f883ccc61044bfffd6e102cca6.out
+++ b/test/expected/test_json_format.sh_40223ac4742883f883ccc61044bfffd6e102cca6.out
@ -11,6 +11,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "TRACE",
        "user": null
    },
    {
@ -25,6 +26,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "INFO",
        "user": null
    },
    {
@ -39,6 +41,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "INFO",
        "user": "steve@example.com"
    },
    {
@ -53,6 +56,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "DEBUG5",
        "user": null
    },
    {
@ -67,6 +71,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "DEBUG4",
        "user": null
    },
    {
@ -81,6 +86,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "DEBUG3",
        "user": null
    },
    {
@ -95,6 +101,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "DEBUG2",
        "user": null
    },
    {
@ -109,6 +116,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "DEBUG",
        "user": null
    },
    {
@ -123,6 +131,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "STATS",
        "user": null
    },
    {
@ -137,6 +146,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "WARNING",
        "user": null
    },
    {
@ -151,6 +161,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "ERROR",
        "user": null
    },
    {
@ -165,6 +176,7 @@
        "log_filters": null,
        "arr": null,
        "obj": null,
+        "lvl": "CRITICAL",
        "user": null
    },
    {
@ -187,6 +199,7 @@
            "field1": "hi",
            "field2": 2
        },
+        "lvl": "FATAL",
        "user": null
    }
 ]
--- a/test/expected/test_json_format.sh_80959e2bb6a7fdf938c2e4dbd7d7c81eb84fa072.out
+++ b/test/expected/test_json_format.sh_80959e2bb6a7fdf938c2e4dbd7d7c81eb84fa072.out
@ -1,6 +1,6 @@
-2013-09-06T20:00:48.124 abc 48 def info  - -
+⋮ abc 48 def info  - -
  @fields: { "lvl": "TRACE", "msg": "trace test"}
-2013-09-06T20:00:49.124 abc 49 def info  - -
+⋮ abc 49 def info  - -
  @fields: { "lvl": "INFO", "msg": "Starting up service"}
 [offset: 186] {"ts": "2013-09-06T22:00:49.124817Z", "@fields": { "lvl": "INFO", "msg":
 parse error: premature EOF
--- a/test/expected/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.out
+++ b/test/expected/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.out
@ -1,14 +1,14 @@
-log_line,log_part,log_time,log_idle_msecs,log_level,log_mark,log_comment,log_tags,log_filters,arr,obj,user
-0,<NULL>,2013-09-06 20:00:48.124,0,trace,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-2,<NULL>,2013-09-06 20:00:49.124,1000,info,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-4,<NULL>,2013-09-06 22:00:49.124,7200000,info,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,steve@example.com
-7,<NULL>,2013-09-06 22:00:59.124,10000,debug5,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-9,<NULL>,2013-09-06 22:00:59.124,0,debug4,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-11,<NULL>,2013-09-06 22:00:59.124,0,debug3,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-13,<NULL>,2013-09-06 22:00:59.124,0,debug2,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-15,<NULL>,2013-09-06 22:00:59.124,0,debug,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-17,<NULL>,2013-09-06 22:01:49.124,50000,stats,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-19,<NULL>,2013-09-06 22:01:49.124,0,warning,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-21,<NULL>,2013-09-06 22:01:49.124,0,error,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-23,<NULL>,2013-09-06 22:01:49.124,0,critical,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>
-25,<NULL>,2013-09-06 22:01:49.124,0,fatal,0,<NULL>,<NULL>,<NULL>,"[""hi"", {""sub1"": true}]","{ ""field1"" : ""hi"", ""field2"": 2 }",<NULL>
+log_line,log_part,log_time,log_idle_msecs,log_level,log_mark,log_comment,log_tags,log_filters,arr,obj,lvl,user
+0,<NULL>,2013-09-06 20:00:48.124,0,trace,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,TRACE,<NULL>
+2,<NULL>,2013-09-06 20:00:49.124,1000,info,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,INFO,<NULL>
+4,<NULL>,2013-09-06 22:00:49.124,7200000,info,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,INFO,steve@example.com
+7,<NULL>,2013-09-06 22:00:59.124,10000,debug5,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,DEBUG5,<NULL>
+9,<NULL>,2013-09-06 22:00:59.124,0,debug4,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,DEBUG4,<NULL>
+11,<NULL>,2013-09-06 22:00:59.124,0,debug3,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,DEBUG3,<NULL>
+13,<NULL>,2013-09-06 22:00:59.124,0,debug2,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,DEBUG2,<NULL>
+15,<NULL>,2013-09-06 22:00:59.124,0,debug,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,DEBUG,<NULL>
+17,<NULL>,2013-09-06 22:01:49.124,50000,stats,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,STATS,<NULL>
+19,<NULL>,2013-09-06 22:01:49.124,0,warning,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,WARNING,<NULL>
+21,<NULL>,2013-09-06 22:01:49.124,0,error,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,ERROR,<NULL>
+23,<NULL>,2013-09-06 22:01:49.124,0,critical,0,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,CRITICAL,<NULL>
+25,<NULL>,2013-09-06 22:01:49.124,0,fatal,0,<NULL>,<NULL>,<NULL>,"[""hi"", {""sub1"": true}]","{ ""field1"" : ""hi"", ""field2"": 2 }",FATAL,<NULL>
--- a/test/expected/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.out
+++ b/test/expected/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.out
@ -1,21 +1,21 @@
-2013-09-06T20:00:48.124 abc 48 def TRACE - trace test
-2013-09-06T20:00:49.124 abc 49 def INFO  - Starting up service
-2013-09-06T22:00:49.124 abc 49 def INFO  - Shutting down service
+⋮ abc 48 def TRACE - trace test
+⋮ abc 49 def INFO  - Starting up service
+⋮ abc 49 def INFO  - Shutting down service
  user: steve@example.com
 timestamp="2013-09-06T22:00:50.123000Z" level="INFO" msg="Hello, World"
 panic: foo bar failed baz
   level1.py:10034
   level2.py:100
   level3.py:42
-2013-09-06T22:00:59.124 abc 59 def DEBUG5 - Details...
-2013-09-06T22:00:59.124 abc 59 def DEBUG4 - Details...
-2013-09-06T22:00:59.124 abc 59 def DEBUG3 - Details...
-2013-09-06T22:00:59.124 abc 59 def DEBUG2 - Details...
-2013-09-06T22:00:59.124 abc 59 def DEBUG - Details...
-2013-09-06T22:01:49.124 abc 49 def STATS - 1 beat per second
-[33m2013-09-06T22:01:49.124[0m[33m [0m[33mabc 49 def[0m[33m WARNING - [0m[33mnot looking good[0m
-[31m2013-09-06T22:01:49.124[0m[31m [0m[31mabc 49 def[0m[31m ERROR - [0m[31mlooking bad[0m
-[31m2013-09-06T22:01:49.124[0m[31m [0m[31mabc 49 def[0m[31m CRITICAL - [0m[31msooo bad[0m
-[31m2013-09-06T22:01:49.124[0m[31m [0m[31mabc 49 def[0m[31m FATAL - [0m[31mshoot[0m
+⋮ abc 59 def DEBUG5 - Details...
+⋮ abc 59 def DEBUG4 - Details...
+⋮ abc 59 def DEBUG3 - Details...
+⋮ abc 59 def DEBUG2 - Details...
+⋮ abc 59 def DEBUG - Details...
+⋮ abc 49 def STATS - 1 beat per second
+[33m⋮[0m[33m [0m[33mabc 49 def[0m[33m WARNING - [0m[33mnot looking good[0m
+[31m⋮[0m[31m [0m[31mabc 49 def[0m[31m ERROR - [0m[31mlooking bad[0m
+[31m⋮[0m[31m [0m[31mabc 49 def[0m[31m CRITICAL - [0m[31msooo bad[0m
+[31m⋮[0m[31m [0m[31mabc 49 def[0m[31m FATAL - [0m[31mshoot[0m
 [31m  obj: { "field1" : "hi", "field2": 2 }[0m
 [31m  arr: ["hi", {"sub1": true}][0m
--- a/test/expected/test_json_format.sh_989e52d167582648b73c5d025cc0e814c642b3c8.out
+++ b/test/expected/test_json_format.sh_989e52d167582648b73c5d025cc0e814c642b3c8.out
@ -1,4 +1,4 @@
-2013-09-06T20:00:49.124 abc 49 def 0     c.e.foo Starting up service
-2013-09-06T22:00:49.124 abc 49 def 0     c.e.foo Shutting down service
+⋮ abc 49 def 0     c.e.foo Starting up service
+⋮ abc 49 def 0     c.e.foo Shutting down service
  user: steve@example.com
-[31m2013-09-06T22:01:49.124[0m[31m [0m[31mabc 49 def[0m[31m 10    c.e.foo [0m[31mlooking bad[0m
+[31m⋮[0m[31m [0m[31mabc 49 def[0m[31m 10    c.e.foo [0m[31mlooking bad[0m
--- a/test/expected/test_json_format.sh_a06b3cdd46b387e72d6faa4cce648b8b11ae870b.out
+++ b/test/expected/test_json_format.sh_a06b3cdd46b387e72d6faa4cce648b8b11ae870b.out
@ -1,25 +1,25 @@
 
-[2013-09-06T20:00:48.124] TRACE trace testbork bork bork
+[2013-09-06T20:00:48.124] ⋮ trace testbork bork bork
 
-[2013-09-06T20:00:49.124] INFO Starting up servicebork bork bork
+[2013-09-06T20:00:49.124] ⋮ Starting up servicebork bork bork
 
-[2013-09-06T22:00:49.124] INFO Shutting down servicebork bork bork
-  user:mailto:steve@example.com
+[2013-09-06T22:00:49.124] ⋮ Shutting down servicebork bork bork
+  user: mailto:steve@example.com
 
-[2013-09-06T22:00:59.124] DEBUG5 Details...bork bork bork
+[2013-09-06T22:00:59.124] ⋮ Details...bork bork bork
 
-[2013-09-06T22:00:59.124] DEBUG4 Details...bork bork bork
+[2013-09-06T22:00:59.124] ⋮ Details...bork bork bork
 
-[2013-09-06T22:00:59.124] DEBUG3 Details...bork bork bork
+[2013-09-06T22:00:59.124] ⋮ Details...bork bork bork
 
-[2013-09-06T22:00:59.124] DEBUG2 Details...bork bork bork
+[2013-09-06T22:00:59.124] ⋮ Details...bork bork bork
 
-[2013-09-06T22:00:59.124] DEBUG Details...bork bork bork
+[2013-09-06T22:00:59.124] ⋮ Details...bork bork bork
 
-[2013-09-06T22:01:49.124] STATS 1 beat per secondbork bork bork
+[2013-09-06T22:01:49.124] ⋮ 1 beat per secondbork bork bork
 
-[33m[[0m[33m2013-09-06T22:01:49.124[0m[33m] WARNING not looking go[0m[33modbork bork bork[0m
+[33m[[0m[33m2013-09-06T22:01:49.124[0m[33m] [0m[33m⋮[0m[33m [0m[33mnot looking goodbork bork bork[0m
 
-[31m[[0m[31m2013-09-06T22:01:49.124[0m[31m] ERROR looking badbor[0m[31mk bork bork[0m
+[31m[[0m[31m2013-09-06T22:01:49.124[0m[31m] [0m[31m⋮[0m[31m [0m[31mlooking bad[0m[31mbork bork bork[0m
 
-[31m[[0m[31m2013-09-06T22:01:49.124[0m[31m] CRITICAL sooo badbork b[0m[31mork bork[0m
+[31m[[0m[31m2013-09-06T22:01:49.124[0m[31m] [0m[31m⋮[0m[31m [0m[31msooo bad[0m[31mbork bork bork[0m
--- a/test/formats/jsontest/format.json
+++ b/test/formats/jsontest/format.json
@ -1,35 +1,45 @@
 {
    "$schema": "https://lnav.org/schemas/format-v1.schema.json",
-    "test_log" : {
-        "title" : "Test JSON Log",
-        "json" : true,
-        "file-pattern" : "logfile_json\\.json",
-        "description" : "Test config",
-        "line-format" : [
+    "test_log": {
+        "title": "Test JSON Log",
+        "json": true,
+        "file-pattern": "logfile_json\\.json",
+        "description": "Test config",
+        "line-format": [
            "\n[",
-            { "field" : "ts" },
+            {
+                "field": "ts"
+            },
            "] ",
-            { "field" : "lvl" },
+            {
+                "field": "lvl"
+            },
            " ",
-            { "field" : "msg" }
+            {
+                "field": "msg"
+            }
        ],
-        "level-field" : "lvl",
+        "level-field": "lvl",
        "timestamp-field": "ts",
-        "body-field" : "msg",
-        "value" : {
-            "msg" : {
-                "rewriter" : ";SELECT :msg || 'bork bork bork'"
+        "body-field": "msg",
+        "value": {
+            "msg": {
+                "rewriter": ";SELECT :msg || 'bork bork bork'"
+            },
+            "arr": {
+                "kind": "json"
            },
-            "arr" : {
-                "kind" : "json"
+            "obj": {
+                "kind": "json"
            },
-            "obj" : {
-                "kind" : "json"
+            "lvl": {
+                "kind": "string",
+                "hidden": true
            },
-            "user" : {
-                "kind" : "string",
-                "identifier" : true,
-                "rewriter" : "|rewrite-user"
+            "user": {
+                "kind": "string",
+                "identifier": true,
+                "rewriter": "|rewrite-user"
            }
        }
    }
--- a/test/logfile_tcf.1
+++ b/test/logfile_tcf.1
@ -1,3 +1,3 @@
-TCF 59:47.191: Server-Properties: {"Name":"TCF Protocol Logger","OSName":"Linux 3.2.0-60-generic","UserName":"xavier","AgentID":"1fde3dd1-d4be-4f79-8090-6f8d212f03bf","TransportName":"TCP","Proxy":"","ValueAdd":"1","Port":"1534"}
-TCF 30:11.474: 0: ---> C 2 RunControl getChildren null <eom>
-TCF 01:11.475: 0: <--- R 2  ["P1"] <eom>
+TCF 59:47.191234: Server-Properties: {"Name":"TCF Protocol Logger","OSName":"Linux 3.2.0-60-generic","UserName":"xavier","AgentID":"1fde3dd1-d4be-4f79-8090-6f8d212f03bf","TransportName":"TCP","Proxy":"","ValueAdd":"1","Port":"1534"}
+TCF 30:11.474442: 0: ---> C 2 RunControl getChildren null <eom>
+TCF 01:11.475557: 0: <--- R 2  ["P1"] <eom>
--- a/test/test_logfile.sh
+++ b/test/test_logfile.sh
@ -371,9 +371,9 @@ EOF
 run_test ${lnav_test} -n ${srcdir}/logfile_tcf.1

 check_output "timestamps with no dates are not rewritten?" <<EOF
-TCF 2014-04-06 09:59:47.191000: Server-Properties: {"Name":"TCF Protocol Logger","OSName":"Linux 3.2.0-60-generic","UserName":"xavier","AgentID":"1fde3dd1-d4be-4f79-8090-6f8d212f03bf","TransportName":"TCP","Proxy":"","ValueAdd":"1","Port":"1534"}
-TCF 2014-04-06 10:30:11.474000: 0: ---> C 2 RunControl getChildren null <eom>
-TCF 2014-04-06 11:01:11.475000: 0: <--- R 2  ["P1"] <eom>
+TCF 2014-04-06 09:59:47.191234: Server-Properties: {"Name":"TCF Protocol Logger","OSName":"Linux 3.2.0-60-generic","UserName":"xavier","AgentID":"1fde3dd1-d4be-4f79-8090-6f8d212f03bf","TransportName":"TCP","Proxy":"","ValueAdd":"1","Port":"1534"}
+TCF 2014-04-06 10:30:11.474442: 0: ---> C 2 RunControl getChildren null <eom>
+TCF 2014-04-06 11:01:11.475557: 0: <--- R 2  ["P1"] <eom>
 EOF