[json-format] preserve sub-second times

Related to #1248

src/base/date_time_scanner.cc

@@ -47,8 +47,14 @@ date_time_scanner::ftime(char* dst,
 {
     off_t off = 0;
 
-    if (time_fmt == nullptr) {
+    if (time_fmt == nullptr || this->dts_fmt_lock == -1
-        PTIMEC_FORMATS[this->dts_fmt_lock].pf_ffunc(dst, off, len, tm);
+        || (tm.et_flags & ETF_MACHINE_ORIENTED))
+    {
+        auto index
+            = this->dts_fmt_lock != -1 && !(tm.et_flags & ETF_MACHINE_ORIENTED)
+            ? this->dts_fmt_lock
+            : PTIMEC_DEFAULT_FMT_INDEX;
+        PTIMEC_FORMATS[index].pf_ffunc(dst, off, len, tm);
         if (tm.et_flags & ETF_SUB_NOT_IN_FORMAT) {
             if (tm.et_flags & ETF_MILLIS_SET) {
                 dst[off++] = '.';
@@ -61,6 +67,9 @@ date_time_scanner::ftime(char* dst,
                 ftime_N(dst, off, len, tm);
             }
         }
+        if (index == PTIMEC_DEFAULT_FMT_INDEX && tm.et_flags & ETF_ZONE_SET) {
+            ftime_z(dst, off, len, tm);
+        }
         dst[off] = '\0';
     } else {
         off = ftime_fmt(dst, len, time_fmt[this->dts_fmt_lock], tm);

src/formats/nextcloud_log.json

@@ -48,8 +48,7 @@
         },
         "line-format": [
             {
-                "field": "__timestamp__",
+                "field": "__timestamp__"
-                "timestamp-format": "%b %e %H:%M:%S"
             },
             " ",
             {

src/log_format.cc

@@ -794,6 +794,7 @@ struct json_log_userdata {
     scan_batch_context* jlu_batch_context;
     nonstd::optional<string_fragment> jlu_opid_frag;
     nonstd::optional<std::string> jlu_subid;
+    struct exttm jlu_exttm;
 };
 
 static int read_json_field(yajlpp_parse_context* ypc,
@@ -844,33 +845,44 @@ read_json_number(yajlpp_parse_context* ypc,
 
         tv.tv_sec = val / divisor;
         tv.tv_usec = fmod(val, divisor) * (1000000.0 / divisor);
-        if (jlu->jlu_format->lf_date_time.dts_local_time) {
+        jlu->jlu_format->lf_date_time.to_localtime(tv.tv_sec, jlu->jlu_exttm);
-            struct tm ltm;
+        tv.tv_sec = tm2sec(&jlu->jlu_exttm.et_tm);
-            localtime_r(&tv.tv_sec, &ltm);
+        jlu->jlu_exttm.et_gmtoff
-#ifdef HAVE_STRUCT_TM_TM_ZONE
+            = jlu->jlu_format->lf_date_time.dts_local_offset_cache;
-            ltm.tm_zone = nullptr;
+        jlu->jlu_exttm.et_flags
-#endif
+            |= ETF_MACHINE_ORIENTED | ETF_SUB_NOT_IN_FORMAT | ETF_ZONE_SET;
-            ltm.tm_isdst = 0;
+        if (divisor == 1000) {
-            tv.tv_sec = tm2sec(&ltm);
+            jlu->jlu_exttm.et_flags |= ETF_MILLIS_SET;
+        } else {
+            jlu->jlu_exttm.et_flags |= ETF_MICROS_SET;
         }
+        jlu->jlu_exttm.et_nsec = jlu->jlu_exttm.et_nsec = tv.tv_usec * 1000;
         jlu->jlu_base_line->set_time(tv);
     } else if (jlu->jlu_format->lf_subsecond_field == field_name) {
         uint64_t millis = 0;
+        jlu->jlu_exttm.et_flags &= ~(ETF_MICROS_SET | ETF_MILLIS_SET);
         switch (jlu->jlu_format->lf_subsecond_unit.value()) {
             case log_format::subsecond_unit::milli:
                 millis = val;
+                jlu->jlu_exttm.et_nsec = val * 1000000;
+                jlu->jlu_exttm.et_flags |= ETF_MILLIS_SET;
                 break;
             case log_format::subsecond_unit::micro:
                 millis = std::chrono::duration_cast<std::chrono::milliseconds>(
                              std::chrono::microseconds((int64_t) val))
                              .count();
+                jlu->jlu_exttm.et_nsec = val * 1000;
+                jlu->jlu_exttm.et_flags |= ETF_MICROS_SET;
                 break;
             case log_format::subsecond_unit::nano:
                 millis = std::chrono::duration_cast<std::chrono::milliseconds>(
                              std::chrono::nanoseconds((int64_t) val))
                              .count();
+                jlu->jlu_exttm.et_nsec = val;
+                jlu->jlu_exttm.et_flags |= ETF_NANOS_SET;
                 break;
         }
+        jlu->jlu_exttm.et_flags |= ETF_SUB_NOT_IN_FORMAT;
         jlu->jlu_base_line->set_millis(millis);
     } else if (jlu->jlu_format->elf_level_field == field_name) {
         if (jlu->jlu_format->elf_level_pairs.empty()) {
@@ -982,6 +994,42 @@ rewrite_json_int(yajlpp_parse_context* ypc, long long val)
     json_log_userdata* jlu = (json_log_userdata*) ypc->ypc_userdata;
     const intern_string_t field_name = ypc->get_path();
 
+    if (jlu->jlu_format->lf_timestamp_field == field_name) {
+        long long divisor = jlu->jlu_format->elf_timestamp_divisor;
+        struct timeval tv;
+
+        tv.tv_sec = val / divisor;
+        tv.tv_usec = fmod(val, divisor) * (1000000.0 / divisor);
+        jlu->jlu_format->lf_date_time.to_localtime(tv.tv_sec, jlu->jlu_exttm);
+        jlu->jlu_exttm.et_gmtoff
+            = jlu->jlu_format->lf_date_time.dts_local_offset_cache;
+        jlu->jlu_exttm.et_flags |= ETF_MACHINE_ORIENTED | ETF_SUB_NOT_IN_FORMAT
+            | ETF_ZONE_SET | ETF_Z_FOR_UTC;
+        if (divisor == 1) {
+            jlu->jlu_exttm.et_flags |= ETF_MICROS_SET;
+        } else {
+            jlu->jlu_exttm.et_flags |= ETF_MILLIS_SET;
+        }
+        jlu->jlu_exttm.et_nsec = jlu->jlu_exttm.et_nsec = tv.tv_usec * 1000;
+    } else if (jlu->jlu_format->lf_subsecond_field == field_name) {
+        jlu->jlu_exttm.et_flags &= ~(ETF_MICROS_SET | ETF_MILLIS_SET);
+        switch (jlu->jlu_format->lf_subsecond_unit.value()) {
+            case log_format::subsecond_unit::milli:
+                jlu->jlu_exttm.et_nsec = val * 1000000;
+                jlu->jlu_exttm.et_flags |= ETF_MILLIS_SET;
+                break;
+            case log_format::subsecond_unit::micro:
+                jlu->jlu_exttm.et_nsec = val * 1000;
+                jlu->jlu_exttm.et_flags |= ETF_MICROS_SET;
+                break;
+            case log_format::subsecond_unit::nano:
+                jlu->jlu_exttm.et_nsec = val;
+                jlu->jlu_exttm.et_flags |= ETF_NANOS_SET;
+                break;
+        }
+        jlu->jlu_exttm.et_flags |= ETF_SUB_NOT_IN_FORMAT;
+    }
+
     if (!ypc->is_level(1) && !jlu->jlu_format->has_value_def(field_name)) {
         return 1;
     }
@@ -998,6 +1046,42 @@ rewrite_json_double(yajlpp_parse_context* ypc, double val)
     json_log_userdata* jlu = (json_log_userdata*) ypc->ypc_userdata;
     const intern_string_t field_name = ypc->get_path();
 
+    if (jlu->jlu_format->lf_timestamp_field == field_name) {
+        long long divisor = jlu->jlu_format->elf_timestamp_divisor;
+        struct timeval tv;
+
+        tv.tv_sec = val / divisor;
+        tv.tv_usec = fmod(val, divisor) * (1000000.0 / divisor);
+        jlu->jlu_format->lf_date_time.to_localtime(tv.tv_sec, jlu->jlu_exttm);
+        jlu->jlu_exttm.et_gmtoff
+            = jlu->jlu_format->lf_date_time.dts_local_offset_cache;
+        jlu->jlu_exttm.et_flags |= ETF_MACHINE_ORIENTED | ETF_SUB_NOT_IN_FORMAT
+            | ETF_ZONE_SET | ETF_Z_FOR_UTC;
+        if (divisor == 1) {
+            jlu->jlu_exttm.et_flags |= ETF_MICROS_SET;
+        } else {
+            jlu->jlu_exttm.et_flags |= ETF_MILLIS_SET;
+        }
+        jlu->jlu_exttm.et_nsec = jlu->jlu_exttm.et_nsec = tv.tv_usec * 1000;
+    } else if (jlu->jlu_format->lf_subsecond_field == field_name) {
+        jlu->jlu_exttm.et_flags &= ~(ETF_MICROS_SET | ETF_MILLIS_SET);
+        switch (jlu->jlu_format->lf_subsecond_unit.value()) {
+            case log_format::subsecond_unit::milli:
+                jlu->jlu_exttm.et_nsec = val * 1000000;
+                jlu->jlu_exttm.et_flags |= ETF_MILLIS_SET;
+                break;
+            case log_format::subsecond_unit::micro:
+                jlu->jlu_exttm.et_nsec = val * 1000;
+                jlu->jlu_exttm.et_flags |= ETF_MICROS_SET;
+                break;
+            case log_format::subsecond_unit::nano:
+                jlu->jlu_exttm.et_nsec = val;
+                jlu->jlu_exttm.et_flags |= ETF_NANOS_SET;
+                break;
+        }
+        jlu->jlu_exttm.et_flags |= ETF_SUB_NOT_IN_FORMAT;
+    }
+
     if (!ypc->is_level(1) && !jlu->jlu_format->has_value_def(field_name)) {
         return 1;
     }
@@ -1839,7 +1923,6 @@ read_json_field(yajlpp_parse_context* ypc, const unsigned char* str, size_t len)
 {
     json_log_userdata* jlu = (json_log_userdata*) ypc->ypc_userdata;
     const intern_string_t field_name = ypc->get_path();
-    struct exttm tm_out;
     struct timeval tv_out;
     auto frag = string_fragment::from_bytes(str, len);
 
@@ -1848,7 +1931,7 @@ read_json_field(yajlpp_parse_context* ypc, const unsigned char* str, size_t len)
             (const char*) str,
             len,
             jlu->jlu_format->get_timestamp_formats(),
-            &tm_out,
+            &jlu->jlu_exttm,
             tv_out);
         if (last == nullptr) {
             auto ls = jlu->jlu_format->lf_date_time.unlock();
@@ -1856,7 +1939,7 @@ read_json_field(yajlpp_parse_context* ypc, const unsigned char* str, size_t len)
                      (const char*) str,
                      len,
                      jlu->jlu_format->get_timestamp_formats(),
-                     &tm_out,
+                     &jlu->jlu_exttm,
                      tv_out))
                 == nullptr)
             {
@@ -1865,7 +1948,7 @@ read_json_field(yajlpp_parse_context* ypc, const unsigned char* str, size_t len)
             if (last != nullptr) {
                 auto old_flags
                     = jlu->jlu_format->lf_timestamp_flags & DATE_TIME_SET_FLAGS;
-                auto new_flags = tm_out.et_flags & DATE_TIME_SET_FLAGS;
+                auto new_flags = jlu->jlu_exttm.et_flags & DATE_TIME_SET_FLAGS;
 
                 // It is unlikely a valid timestamp would lose much
                 // precision.
@@ -1875,7 +1958,7 @@ read_json_field(yajlpp_parse_context* ypc, const unsigned char* str, size_t len)
             }
         }
         if (last != nullptr) {
-            jlu->jlu_format->lf_timestamp_flags = tm_out.et_flags;
+            jlu->jlu_format->lf_timestamp_flags = jlu->jlu_exttm.et_flags;
             jlu->jlu_base_line->set_time(tv_out);
         }
     } else if (jlu->jlu_format->elf_level_pointer.pp_value != nullptr) {
@@ -1937,15 +2020,17 @@ rewrite_json_field(yajlpp_parse_context* ypc,
         char time_buf[64];
 
         // TODO add a timeval kind to logline_value
-        if (jlu->jlu_line->is_time_skewed()) {
+        if (jlu->jlu_line->is_time_skewed()
+            || (jlu->jlu_format->lf_timestamp_flags
+                & (ETF_MICROS_SET | ETF_NANOS_SET | ETF_ZONE_SET)))
+        {
             struct timeval tv;
-            struct exttm tm;
 
             const auto* last = jlu->jlu_format->lf_date_time.scan(
                 (const char*) str,
                 len,
                 jlu->jlu_format->get_timestamp_formats(),
-                &tm,
+                &jlu->jlu_exttm,
                 tv);
             if (last == nullptr) {
                 auto ls = jlu->jlu_format->lf_date_time.unlock();
@@ -1953,18 +2038,29 @@ rewrite_json_field(yajlpp_parse_context* ypc,
                          (const char*) str,
                          len,
                          jlu->jlu_format->get_timestamp_formats(),
-                         &tm,
+                         &jlu->jlu_exttm,
                          tv))
                     == nullptr)
                 {
                     jlu->jlu_format->lf_date_time.relock(ls);
                 }
             }
-            sql_strftime(time_buf, sizeof(time_buf), tv, 'T');
+            jlu->jlu_format->lf_date_time.ftime(
+                time_buf,
+                sizeof(time_buf),
+                jlu->jlu_format->get_timestamp_formats(),
+                jlu->jlu_exttm);
         } else {
             sql_strftime(
                 time_buf, sizeof(time_buf), jlu->jlu_line->get_timeval(), 'T');
         }
+        if (jlu->jlu_exttm.et_flags & ETF_ZONE_SET
+            && jlu->jlu_format->lf_date_time.dts_zoned_to_local)
+        {
+            jlu->jlu_exttm.et_flags &= ~ETF_Z_IS_UTC;
+        }
+        jlu->jlu_exttm.et_gmtoff
+            = jlu->jlu_format->lf_date_time.dts_local_offset_cache;
         jlu->jlu_format->jlf_line_values.lvv_values.emplace_back(
             jlu->jlu_format->get_value_meta(field_name,
                                             value_kind_t::VALUE_TEXT),
@@ -2229,17 +2325,22 @@ external_log_format::get_subline(const logline& ll,
                             struct line_range lr;
                             ssize_t ts_len;
                             char ts[64];
+                            struct exttm et;
 
+                            ll.to_exttm(et);
+                            et.et_nsec += jlu.jlu_exttm.et_nsec % 1000000;
+                            et.et_gmtoff = jlu.jlu_exttm.et_gmtoff;
+                            et.et_flags |= jlu.jlu_exttm.et_flags;
                             if (!jfe.jfe_prefix.empty()) {
                                 this->json_append_to_cache(jfe.jfe_prefix);
                             }
                             if (jfe.jfe_ts_format.empty()) {
-                                ts_len = sql_strftime(
+                                ts_len = this->lf_date_time.ftime(
-                                    ts, sizeof(ts), ll.get_timeval(), 'T');
+                                    ts,
+                                    sizeof(ts),
+                                    this->get_timestamp_formats(),
+                                    et);
                             } else {
-                                struct exttm et;
-
-                                ll.to_exttm(et);
                                 ts_len = ftime_fmt(ts,
                                                    sizeof(ts),
                                                    jfe.jfe_ts_format.c_str(),
@@ -2759,6 +2860,7 @@ external_log_format::build(std::vector<lnav::console::user_message>& errors)
         if (this->elf_type == elf_type_t::ELF_TYPE_JSON) {
             this->lf_multiline = true;
             this->lf_structured = true;
+            this->lf_formatted_lines = true;
             this->jlf_parse_context
                 = std::make_shared<yajlpp_parse_context>(this->elf_name);
             this->jlf_yajl_handle.reset(

src/log_format.hh

@@ -562,6 +562,7 @@ public:
     uint8_t lf_mod_index{0};
     bool lf_multiline{true};
     bool lf_structured{false};
+    bool lf_formatted_lines{false};
     date_time_scanner lf_date_time;
     date_time_scanner lf_time_scanner;
     std::vector<pattern_for_lines> lf_pattern_locks;

src/logfile_sub_source.cc

@@ -319,7 +319,7 @@ logfile_sub_source::text_value_for_line(textview_curses& tc,
         this->lss_token_attrs.emplace_back(lr, SA_ORIGINAL_LINE.value());
     }
 
-    if (!this->lss_token_line->is_continued()
+    if (!this->lss_token_line->is_continued() && !format->lf_formatted_lines
         && (this->lss_token_file->is_time_adjusted()
             || ((format->lf_timestamp_flags & ETF_ZONE_SET
                  || format->lf_date_time.dts_default_zone != nullptr)

src/ptimec.c

@@ -145,8 +145,12 @@ main(int argc, char* argv[])
         printf("}\n\n");
     }
 
+    size_t default_format_index = 0;
     printf("struct ptime_fmt PTIMEC_FORMATS[] = {\n");
     for (int lpc = 1; lpc < argc; lpc++) {
+        if (strcmp(argv[lpc], "%Y-%m-%dT%H:%M:%S") == 0) {
+            default_format_index = lpc - 1;
+        }
         printf("    { \"%s\", ptime_f%d, ftime_f%d },\n", argv[lpc], lpc, lpc);
     }
     printf("\n");
@@ -161,5 +165,8 @@ main(int argc, char* argv[])
     printf("    nullptr\n");
     printf("};\n");
 
+    printf("\n");
+    printf("size_t PTIMEC_DEFAULT_FMT_INDEX = %zu;\n", default_format_index);
+
     return retval;
 }

src/ptimec.hh

@@ -520,7 +520,8 @@ ptime_i(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
     secs2tm(epoch, &dst->et_tm);
     dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
         | ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MILLIS_SET
-        | ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME | ETF_ZONE_SET;
+        | ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME | ETF_ZONE_SET
+        | ETF_SUB_NOT_IN_FORMAT;
 
     return (epoch_ms > 0);
 }
@@ -557,7 +558,8 @@ ptime_6(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
     secs2tm(epoch, &dst->et_tm);
     dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
         | ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MICROS_SET
-        | ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME | ETF_ZONE_SET;
+        | ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME | ETF_ZONE_SET
+        | ETF_SUB_NOT_IN_FORMAT | ETF_Z_FOR_UTC;
 
     return (epoch_us > 0);
 }
@@ -1285,4 +1287,6 @@ extern struct ptime_fmt PTIMEC_FORMATS[];
 
 extern const char* PTIMEC_FORMAT_STR[];
 
+extern size_t PTIMEC_DEFAULT_FMT_INDEX;
+
 #endif

src/time_formats.am

@@ -25,8 +25,8 @@ TIME_FORMATS = \
     "%Y-%m-%dT%H:%M:%S.%L%z" \
     "%y-%m-%dT%H:%M:%S.%L%z" \
     "%Y-%m-%dT%H:%M:%S%z" \
-    "%Y-%m-%dT%H:%M:%S" \
     "%Y-%m-%dT%H:%M:%S%z" \
+    "%Y-%m-%dT%H:%M:%S" \
     "%Y-%m-%dT%H:%M" \
     "%Y/%m/%d %H:%M:%S %z" \
     "%Y/%m/%d %H:%M:%S%z" \

test/expected/test_json_format.sh_4315a3d6124c14cbe3c474b6dbf4cc8720a9859f.out

@@ -1,3 +1,3 @@
-2017-03-24T20:06:26.240 1.1.1.1 GET 200   443 /example/uri/5
+2017-03-24T20:06:26.240Z 1.1.1.1 GET 200   443 /example/uri/5
-2017-03-24T20:12:47.764 1.1.1.1 GET 500  4433 /example/uri/5
+2017-03-24T20:12:47.764Z 1.1.1.1 GET 500  4433 /example/uri/5
-2017-03-24T20:15:31.694 1.1.1.1 GET 400 44345 /example/uri/5
+2017-03-24T20:15:31.694Z 1.1.1.1 GET 400 44345 /example/uri/5

test/expected/test_json_format.sh_469f005b0708d629bc95f0c48a5e390f440c1fef.out

@@ -1,29 +1,29 @@
 
-[2013-09-06T20:00:48.124] ⋮ <c.e.foo.bar.bazzer  > trace test
+[2013-09-06T20:00:48.124817Z] ⋮ <c.e.foo.bar.bazzer  > trace test
 
-[2013-09-06T20:00:49.124] ⋮ <com.example.demo    > Starting up service
+[2013-09-06T20:00:49.124817Z] ⋮ <com.example.demo    > Starting up service
 
-[2013-09-06T22:00:49.124] ⋮ Shutting down service
+[2013-09-06T22:00:49.124817Z] ⋮ Shutting down service
   user: steve@example.com
 
-[2013-09-06T22:00:59.124] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 
-[2013-09-06T22:00:59.124] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 
-[2013-09-06T22:00:59.124] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 
-[2013-09-06T22:00:59.124] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 
-[2013-09-06T22:01:00.000] ⋮ Details...
+[2013-09-06 22:01:00Z] ⋮ Details...
 
-[2013-09-06T22:01:49.124] ⋮ 1 beat per second
+[2013-09-06T22:01:49.124817Z] ⋮ 1 beat per second
 
-[2013-09-06T22:01:49.124] ⋮ not looking good
+[2013-09-06T22:01:49.124817Z] ⋮ not looking good
 
-[2013-09-06T22:01:49.124] ⋮ looking bad
+[2013-09-06T22:01:49.124817Z] ⋮ looking bad
 
-[2013-09-06T22:01:49.124] ⋮ sooo bad
+[2013-09-06T22:01:49.124817Z] ⋮ sooo bad
 
-[2013-09-06T22:01:49.124] ⋮ shoot
+[2013-09-06T22:01:49.124817Z] ⋮ shoot
   obj: { "field1" : "hi", "field2": 2 }
   arr: ["hi", {"sub1": true}]

test/expected/test_json_format.sh_7724d1a96d74d4418dd44d7416270f9bb64b2564.out

@@ -1,29 +1,29 @@
-2013-09-06T20:00:48.124000Z TRACE trace test
+2013-09-06T20:00:48.124817Z TRACE trace test
   @fields: { "lvl": "TRACE", "msg": "trace test"}
-2013-09-06T20:00:49.124000Z INFO Starting up service
+2013-09-06T20:00:49.124817Z INFO Starting up service
   @fields: { "lvl": "INFO", "msg": "Starting up service"}
-2013-09-06T22:00:49.124000Z INFO Shutting down service
+2013-09-06T22:00:49.124817Z INFO Shutting down service
   @fields/user: steve@example.com
   @fields: { "lvl": "INFO", "msg": "Shutting down service", "user": "steve@example.com"}
-2013-09-06T22:00:59.124000Z DEBUG5 Details...
+2013-09-06T22:00:59.124817Z DEBUG5 Details...
   @fields: { "lvl": "DEBUG5", "msg": "Details..."}
-2013-09-06T22:00:59.124000Z DEBUG4 Details...
+2013-09-06T22:00:59.124817Z DEBUG4 Details...
   @fields: { "lvl": "DEBUG4", "msg": "Details..."}
-2013-09-06T22:00:59.124000Z DEBUG3 Details...
+2013-09-06T22:00:59.124817Z DEBUG3 Details...
   @fields: { "lvl": "DEBUG3", "msg": "Details..."}
-2013-09-06T22:00:59.124000Z DEBUG2 Details...
+2013-09-06T22:00:59.124817Z DEBUG2 Details...
   @fields: { "lvl": "DEBUG2", "msg": "Details..."}
-2013-09-06T22:00:59.124000Z DEBUG Details...
+2013-09-06T22:00:59.124817Z DEBUG Details...
   @fields: { "lvl": "DEBUG", "msg": "Details..."}
-2013-09-06T22:01:49.124000Z STATS 1 beat per second
+2013-09-06T22:01:49.124817Z STATS 1 beat per second
   @fields: { "lvl": "STATS", "msg": "1 beat per second"}
-2013-09-06T22:01:49.124000Z WARNING not looking good
+2013-09-06T22:01:49.124817Z WARNING not looking good
   @fields: { "lvl": "WARNING", "msg": "not looking good"}
-2013-09-06T22:01:49.124000Z ERROR looking bad
+2013-09-06T22:01:49.124817Z ERROR looking bad
   @fields: { "lvl": "ERROR", "msg": "looking bad"}
-2013-09-06T22:01:49.124000Z CRITICAL sooo bad
+2013-09-06T22:01:49.124817Z CRITICAL sooo bad
   @fields: { "lvl": "CRITICAL", "msg": "sooo bad"}
-2013-09-06T22:01:49.124000Z FATAL shoot
+2013-09-06T22:01:49.124817Z FATAL shoot
   @fields/trace#: line:1
   @fields/trace#: line:2
   @fields: { "lvl": "FATAL", "msg": "shoot", "trace": ["line:1", "line:2"]}

test/expected/test_json_format.sh_7c6529f6bf4a0cb565f5665fdcba032f0ae1ebbe.out

@@ -1,12 +1,12 @@
-2013-09-06T20:00:48.124000Z TRACE trace test
+2013-09-06T20:00:48.124817Z TRACE trace test
   @fields: { "lvl": "TRACE", "msg": "trace test"}
-2013-09-06T20:00:49.124000Z INFO Starting up service
+2013-09-06T20:00:49.124817Z INFO Starting up service
   @fields: { "lvl": "INFO", "msg": "Starting up service"}
 [offset: 186] {"ts": "2013-09-06T22:00:49.124817Z", "@fields": { "lvl": "INFO", "msg": "Shutting down service\nline2\nline3\nline4\nline5\nline6\nline7\nline8\nline9\nline10
 parse error: premature EOF
                                        {"ts": "2013-09-06T22:00:49.124
                      (right here) ------^
-2013-09-06T22:00:59.124000Z DEBUG5 Details...
+2013-09-06T22:00:59.124817Z DEBUG5 Details...
   @fields: { "lvl": "DEBUG5", "msg": "Details..."}
-2013-09-06T22:00:59.222000Z DEBUG4 Details...
+2013-09-06T22:00:59.222222Z DEBUG4 Details...
   @fields: { "lvl": "DEBUG4", "msg": "Details..."}

test/expected/test_json_format.sh_80959e2bb6a7fdf938c2e4dbd7d7c81eb84fa072.out

@@ -1,6 +1,6 @@
-2013-09-06T20:00:48.124000Z TRACE trace test
+2013-09-06T20:00:48.124817Z TRACE trace test
   @fields: { "lvl": "TRACE", "msg": "trace test"}
-2013-09-06T20:00:49.124000Z INFO Starting up service
+2013-09-06T20:00:49.124817Z INFO Starting up service
   @fields: { "lvl": "INFO", "msg": "Starting up service"}
 [offset: 186] {"ts": "2013-09-06T22:00:49.124817Z", "@fields": { "lvl": "INFO", "msg":
 parse error: premature EOF

test/expected/test_json_format.sh_84a71e94dc34661a70bb9015b67ba00e93e9cfb5.out

@@ -1,2 +1,2 @@
-2018-08-21 14:04:21.221000 38708007 medusa-GpsLocator.service python[184] FATAL GPS Reference longitude: 7.358143333
+2018-08-21T14:04:21.221373Z 38708007 medusa-GpsLocator.service python[184] FATAL GPS Reference longitude: 7.358143333
-2018-08-21 14:04:21.221000 38708007 medusa-GpsLocator.service python[184] INFO GPS Reference latitude: 46.908706667
+2018-08-21T14:04:21.221373Z 38708007 medusa-GpsLocator.service python[184] INFO GPS Reference latitude: 46.908706667

test/expected/test_json_format.sh_952297a90e312d2184fe3e4df795ddc731b096c9.out

@@ -1,4 +1,4 @@
 
-[-09-06T22:00:49.124] INFO     Shutting down service
+[-09-06T22:00:49.124817Z] INFO     Shutting down service
   user: steve@example.com
 

test/expected/test_json_format.sh_a06b3cdd46b387e72d6faa4cce648b8b11ae870b.out

@@ -1,29 +1,29 @@
 
-[2013-09-06T20:00:48.124000Z] ⋮ <c.e.foo.bar.bazzer  > trace testbork bork bork
+[2013-09-06T20:00:48.124817Z] ⋮ <c.e.foo.bar.bazzer  > trace testbork bork bork
 
-[2013-09-06T20:00:49.124000Z] ⋮ <com.example.demo    > Starting up servicebork bork bork
+[2013-09-06T20:00:49.124817Z] ⋮ <com.example.demo    > Starting up servicebork bork bork
 
-[2013-09-06T22:00:49.124000Z] ⋮ Shutting down servicebork bork bork
+[2013-09-06T22:00:49.124817Z] ⋮ Shutting down servicebork bork bork
   user: mailto:steve@example.com
 
-[2013-09-06T22:00:59.124000Z] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 bork bork bork
 
-[2013-09-06T22:00:59.124000Z] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 bork bork bork
 
-[2013-09-06T22:00:59.124000Z] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 bork bork bork
 
-[2013-09-06T22:00:59.124000Z] ⋮ Details...
+[2013-09-06T22:00:59.124817Z] ⋮ Details...
 bork bork bork
 
-[2013-09-06T22:01:00.000000Z] ⋮ Details...bork bork bork
+[2013-09-06 22:01:00Z] ⋮ Details...bork bork bork
 
-[2013-09-06T22:01:49.124000Z] ⋮ 1 beat per secondbork bork bork
+[2013-09-06T22:01:49.124817Z] ⋮ 1 beat per secondbork bork bork
 
-[2013-09-06T22:01:49.124000Z] ⋮ not looking goodbork bork bork
+[2013-09-06T22:01:49.124817Z] ⋮ not looking goodbork bork bork
 
-[2013-09-06T22:01:49.124000Z] ⋮ looking badbork bork bork
+[2013-09-06T22:01:49.124817Z] ⋮ looking badbork bork bork
 
-[2013-09-06T22:01:49.124000Z] ⋮ sooo badbork bork bork
+[2013-09-06T22:01:49.124817Z] ⋮ sooo badbork bork bork

test/expected/test_json_format.sh_c1a23804c39b0f74642286d69865ee9d0961a58a.out

@@ -1,2 +1,2 @@
-2022-09-24T00:00:09.484 Hello, World!
+2022-09-24T00:00:09.484000000Z Hello, World!
-2022-09-24T00:00:19.222 Goodbye, World!
+2022-09-24T00:00:19.222000123Z Goodbye, World!

test/expected/test_json_format.sh_d7362cffc8335c2fe6b6527315de59bd6f5dcc7f.out

@@ -1,3 +1,3 @@
-2017-03-24T16:06:26.240 1.1.1.1 GET 200   443 /example/uri/5
+2017-03-24T16:06:26.240-0400 1.1.1.1 GET 200   443 /example/uri/5
-2017-03-24T16:12:47.764 1.1.1.1 GET 500  4433 /example/uri/5
+2017-03-24T16:12:47.764-0400 1.1.1.1 GET 500  4433 /example/uri/5
-2017-03-24T16:15:31.694 1.1.1.1 GET 400 44345 /example/uri/5
+2017-03-24T16:15:31.694-0400 1.1.1.1 GET 400 44345 /example/uri/5

test/expected/test_json_format.sh_f740026626ab554dacb249762d8be7d6539b8c6e.out

@@ -1,2 +1,2 @@
 
-[2013-09-06T20:00:49.124] ⋮ <com.example.demo    > Starting up service
+[2013-09-06T20:00:49.124817Z] ⋮ <com.example.demo    > Starting up service

test/expected/test_json_format.sh_fe19b7ebd349cd689b3f5c22618eab5ce995e68e.out

@@ -1,4 +1,4 @@
--09-06T22:00:49.124 INFO Shutting down service
+-09-06T22:00:49.124817Z INFO Shutting down service
   @fields/user: steve@example.com
   @fields: { "lvl": "INFO", "msg": "Shutting down service", "user": "steve@example.com"}
 

test/logfile_json_subsec.json

@@ -1,2 +1,2 @@
 {"instant":{"epochSecond": 1663977609,"nanoOfSecond": 484000000}, "msg": "Hello, World!"}
-{"instant":{"epochSecond": 1663977619,"nanoOfSecond": 222000000}, "msg": "Goodbye, World!"}
+{"instant":{"epochSecond": 1663977619,"nanoOfSecond": 222000123}, "msg": "Goodbye, World!"}