[json-log] change how lines that do not start with a curly are reported

src/base/intern_string.hh

@@ -62,6 +62,12 @@ struct string_fragment {
         return string_fragment{str, 0, str != nullptr ? (int) strlen(str) : 0};
     }
 
+    static string_fragment from_c_str(const unsigned char* str)
+    {
+        return string_fragment{
+            str, 0, str != nullptr ? (int) strlen((char*) str) : 0};
+    }
+
     template<typename T, std::size_t N>
     static string_fragment from_const(const T (&str)[N])
     {
@@ -277,6 +283,18 @@ struct string_fragment {
             this->sf_string, this->sf_begin + begin, this->sf_begin + end};
     }
 
+    size_t count(char ch) const {
+        size_t retval = 0;
+
+        for (int lpc = this->sf_begin; lpc < this->sf_end; lpc++) {
+            if (this->sf_string[lpc] == ch) {
+                retval += 1;
+            }
+        }
+
+        return retval;
+    }
+
     nonstd::optional<size_t> find(char ch) const
     {
         for (int lpc = this->sf_begin; lpc < this->sf_end; lpc++) {

src/log_format.cc

@@ -708,8 +708,21 @@ external_log_format::scan(logfile& lf,
                           scan_batch_context& sbc)
 {
     if (this->elf_type == elf_type_t::ELF_TYPE_JSON) {
-        yajlpp_parse_context& ypc = *(this->jlf_parse_context);
         logline ll(li.li_file_range.fr_offset, 0, 0, LEVEL_INFO);
+        auto line_frag = sbr.to_string_fragment();
+
+        if (!line_frag.startswith("{")) {
+            if (!this->lf_specialized) {
+                return log_format::SCAN_NO_MATCH;
+            }
+
+            ll.set_time(dst.back().get_timeval());
+            ll.set_level(LEVEL_INVALID);
+            dst.emplace_back(ll);
+            return log_format::SCAN_MATCH;
+        }
+
+        auto& ypc = *(this->jlf_parse_context);
         yajl_handle handle = this->jlf_yajl_handle.get();
         json_log_userdata jlu(sbr, &sbc);
 
@@ -750,10 +763,10 @@ external_log_format::scan(logfile& lf,
                     ll.set_ignore(true);
                     dst.emplace_back(ll);
                     return log_format::SCAN_MATCH;
-                } else {
-                    log_debug("no match! %.*s", sbr.length(), line_data);
-                    return log_format::SCAN_NO_MATCH;
                 }
+
+                log_debug("no match! %.*s", sbr.length(), line_data);
+                return log_format::SCAN_NO_MATCH;
             }
 
             jlu.jlu_sub_line_count += this->jlf_line_format_init_count;
@@ -772,11 +785,11 @@ external_log_format::scan(logfile& lf,
             msg = yajl_get_error(
                 handle, 1, (const unsigned char*) sbr.get_data(), sbr.length());
             if (msg != nullptr) {
+                auto msg_frag = string_fragment::from_c_str(msg);
                 log_debug("Unable to parse line at offset %d: %s",
                           li.li_file_range.fr_offset,
                           msg);
-                line_count
-                    = std::count(msg, msg + strlen((char*) msg), '\n') + 1;
+                line_count = msg_frag.count('\n') + 1;
                 yajl_free_error(handle, msg);
             }
             if (!this->lf_specialized) {
@@ -785,7 +798,7 @@ external_log_format::scan(logfile& lf,
             for (int lpc = 0; lpc < line_count; lpc++) {
                 log_level_t level = LEVEL_INVALID;
 
-                ll.set_time(dst.back().get_time());
+                ll.set_time(dst.back().get_timeval());
                 if (lpc > 0) {
                     level = (log_level_t) (level | LEVEL_CONTINUED);
                 }
@@ -1018,7 +1031,8 @@ external_log_format::module_scan(string_fragment body_cap,
         int curr_fmt = -1, fmt_lock = -1;
 
         while (::next_format(elf->elf_pattern_order, curr_fmt, fmt_lock)) {
-            static thread_local auto md = lnav::pcre2pp::match_data::unitialized();
+            static thread_local auto md
+                = lnav::pcre2pp::match_data::unitialized();
 
             auto& fpat = elf->elf_pattern_order[curr_fmt];
             auto& pat = fpat->p_pcre;
@@ -1389,7 +1403,7 @@ external_log_format::get_subline(const logline& ll,
     if (this->jlf_cached_offset != ll.get_offset()
         || this->jlf_cached_full != full_message)
     {
-        yajlpp_parse_context& ypc = *(this->jlf_parse_context);
+        auto& ypc = *(this->jlf_parse_context);
         yajl_handle handle = this->jlf_yajl_handle.get();
         json_log_userdata jlu(sbr, nullptr);
 
@@ -1399,6 +1413,26 @@ external_log_format::get_subline(const logline& ll,
         this->jlf_line_offsets.clear();
         this->jlf_line_attrs.clear();
 
+        auto line_frag = sbr.to_string_fragment();
+
+        if (!line_frag.startswith("{")) {
+            this->jlf_cached_line.resize(line_frag.length());
+            memcpy(this->jlf_cached_line.data(),
+                   line_frag.data(),
+                   line_frag.length());
+            this->jlf_line_values.clear();
+            sbr.share(this->jlf_share_manager,
+                      &this->jlf_cached_line[0],
+                      this->jlf_cached_line.size());
+            this->jlf_line_values.lvv_sbr = sbr;
+            this->jlf_line_attrs.emplace_back(
+                line_range{0, -1},
+                SA_INVALID.value(fmt::format(
+                    FMT_STRING("line at offset {} is not a JSON-line"),
+                    ll.get_offset())));
+            return;
+        }
+
         yajl_reset(handle);
         ypc.set_static_handler(json_log_rewrite_handlers.jpc_children[0]);
         ypc.ypc_userdata = &jlu;

test/Makefile.am

@@ -304,6 +304,7 @@ dist_noinst_DATA = \
 	logfile_haproxy.0 \
 	logfile_invalid_json.json \
 	logfile_invalid_json2.json \
+	logfile_mixed_json2.json \
 	logfile_journald.json \
 	logfile_json.json \
 	logfile_json2.json \

test/expected/expected.am

@@ -272,6 +272,8 @@ EXPECTED_FILES = \
     $(srcdir)/%reldir%/test_json_format.sh_84a71e94dc34661a70bb9015b67ba00e93e9cfb5.out \
     $(srcdir)/%reldir%/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.err \
     $(srcdir)/%reldir%/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.out \
+    $(srcdir)/%reldir%/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.err \
+    $(srcdir)/%reldir%/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.out \
     $(srcdir)/%reldir%/test_json_format.sh_952297a90e312d2184fe3e4df795ddc731b096c9.err \
     $(srcdir)/%reldir%/test_json_format.sh_952297a90e312d2184fe3e4df795ddc731b096c9.out \
     $(srcdir)/%reldir%/test_json_format.sh_989e52d167582648b73c5d025cc0e814c642b3c8.err \

test/expected/test_json_format.sh_80959e2bb6a7fdf938c2e4dbd7d7c81eb84fa072.out

@@ -1,6 +1,6 @@
-2013-09-06T20:00:48.124 TRACE trace test
+2013-09-06T20:00:48.124 abc 48 def info  - -
   @fields: { "lvl": "TRACE", "msg": "trace test"}
-2013-09-06T20:00:49.124 INFO Starting up service
+2013-09-06T20:00:49.124 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

test/expected/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.out

@@ -0,0 +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
+  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
+2013-09-06T22:01:49.124 abc 49 def WARNING - not looking good
+2013-09-06T22:01:49.124 abc 49 def ERROR - looking bad
+2013-09-06T22:01:49.124 abc 49 def CRITICAL - sooo bad
+2013-09-06T22:01:49.124 abc 49 def FATAL - shoot
+  obj: { "field1" : "hi", "field2": 2 }
+  arr: ["hi", {"sub1": true}]

test/formats/jsontest2/format.json

@@ -3,7 +3,7 @@
     "json_log2": {
         "title": "Test JSON Log with integer levels",
         "json": true,
-        "file-pattern": "logfile_json2\\.json",
+        "file-pattern": "logfile_.*json2\\.json",
         "description": "Test config",
         "line-format": [
             {
@@ -15,26 +15,34 @@
                 "timestamp-format": "abc %S def"
             },
             " ",
-            { "field" : "lvl", "min-width": 5 },
+            {
+                "field": "lvl",
+                "min-width": 5
+            },
             " ",
-            { "field" : "cl", "max-width": 5},
+            {
+                "field": "cl",
+                "max-width": 5
+            },
             " ",
-            { "field" : "msg" }
+            {
+                "field": "msg"
+            }
         ],
-        "level-field" : "lvl",
-        "level" : {
-            "info" : 0,
-            "error" : 10
+        "level-field": "lvl",
+        "level": {
+            "info": 0,
+            "error": 10
         },
         "timestamp-field": "ts",
-        "body-field" : "msg",
-        "value" : {
-            "user" : {
-                "kind" : "string",
-                "identifier" : true
+        "body-field": "msg",
+        "value": {
+            "user": {
+                "kind": "string",
+                "identifier": true
             },
-            "cl" : {
-                "kind" : "string"
+            "cl": {
+                "kind": "string"
             }
         }
     }

test/formats/jsontest3/format.json

@@ -3,7 +3,7 @@
     "json_log3": {
         "title": "Test JSON Log Format",
         "description": "Test JSON Log Format",
-        "file-pattern": "logfile_json3\\.json",
+        "file-pattern": "logfile_.*json3\\.json",
         "json": true,
         "hide-extra": true,
         "convert-to-local-time": true,

test/logfile_mixed_json2.json

@@ -0,0 +1,18 @@
+{"ts": "2013-09-06T20:00:48.124817Z", "lvl": "TRACE", "msg": "trace test"}
+{"ts": "2013-09-06T20:00:49.124817Z", "lvl": "INFO", "msg": "Starting up service"}
+{"ts": "2013-09-06T22:00:49.124817Z", "lvl": "INFO", "msg": "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
+{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG5", "msg": "Details..."}
+{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG4", "msg": "Details..."}
+{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG3", "msg": "Details..."}
+{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG2", "msg": "Details..."}
+{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG", "msg": "Details..."}
+{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "STATS", "msg": "1 beat per second"}
+{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "WARNING", "msg": "not looking good"}
+{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "ERROR", "msg": "looking bad"}
+{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "CRITICAL", "msg": "sooo bad"}
+{"ts": "2013-09-06T22:01:49.124817Z", "lvl": "FATAL", "msg": "shoot", "obj": { "field1" : "hi", "field2": 2 }, "arr" : ["hi", {"sub1": true}]}

test/test_json_format.sh

@@ -131,3 +131,7 @@ run_cap_test ${lnav_test} -n \
     -d /tmp/lnav.err \
     -I ${test_dir} \
     ${test_dir}/logfile_invalid_json2.json
+
+run_cap_test ${lnav_test} -n \
+    -I ${test_dir} \
+    ${test_dir}/logfile_mixed_json2.json