diff --git a/src/base/attr_line.cc b/src/base/attr_line.cc index db9c0f17..b65f4bac 100644 --- 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)) { diff --git a/src/formats/tcf_log.json b/src/formats/tcf_log.json index ad42d781..335d3ff4 100644 --- a/src/formats/tcf_log.json +++ b/src/formats/tcf_log.json @@ -9,7 +9,7 @@ ], "regex": { "std": { - "pattern": "^TCF (?\\d{2}:\\d{2}.\\d{3}): (?:Server-Properties: (?:.*)|channel server|\\w+: (?--->|<---) (?\\w)(?: (?\\w+))?(?: (?\\w+))?(?: (?\\w+))?(?: (?.*))?(?: ))(?.*)$" + "pattern": "^TCF (?\\d{2}:\\d{2}.\\d{3,6}): (?:Server-Properties: (?:.*)|channel server|\\w+: (?--->|<---) (?\\w)(?: (?\\w+))?(?: (?\\w+))?(?: (?\\w+))?(?: (?.*))?(?: ))(?.*)$" } }, "value": { diff --git a/src/log_format.cc b/src/log_format.cc index 3068b306..f8b26bee 100644 --- 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; } diff --git a/src/log_format_ext.hh b/src/log_format_ext.hh index cafa8461..f4f4eaaa 100644 --- 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 jlf_line_offsets; std::vector jlf_cached_line; diff --git a/src/logfile_sub_source.cc b/src/logfile_sub_source.cc index db87ae8f..ae19db1c 100644 --- 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( @@ -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)); } diff --git a/test/expected/test_json_format.sh_40223ac4742883f883ccc61044bfffd6e102cca6.out b/test/expected/test_json_format.sh_40223ac4742883f883ccc61044bfffd6e102cca6.out index 463a7347..0dc139f6 100644 --- 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 } ] diff --git a/test/expected/test_json_format.sh_80959e2bb6a7fdf938c2e4dbd7d7c81eb84fa072.out b/test/expected/test_json_format.sh_80959e2bb6a7fdf938c2e4dbd7d7c81eb84fa072.out index bae2626a..d1f34863 100644 --- 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 diff --git a/test/expected/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.out b/test/expected/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.out index 80919e8d..660e90e0 100644 --- 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,,2013-09-06 20:00:48.124,0,trace,0,,,,,, -2,,2013-09-06 20:00:49.124,1000,info,0,,,,,, -4,,2013-09-06 22:00:49.124,7200000,info,0,,,,,,steve@example.com -7,,2013-09-06 22:00:59.124,10000,debug5,0,,,,,, -9,,2013-09-06 22:00:59.124,0,debug4,0,,,,,, -11,,2013-09-06 22:00:59.124,0,debug3,0,,,,,, -13,,2013-09-06 22:00:59.124,0,debug2,0,,,,,, -15,,2013-09-06 22:00:59.124,0,debug,0,,,,,, -17,,2013-09-06 22:01:49.124,50000,stats,0,,,,,, -19,,2013-09-06 22:01:49.124,0,warning,0,,,,,, -21,,2013-09-06 22:01:49.124,0,error,0,,,,,, -23,,2013-09-06 22:01:49.124,0,critical,0,,,,,, -25,,2013-09-06 22:01:49.124,0,fatal,0,,,,"[""hi"", {""sub1"": true}]","{ ""field1"" : ""hi"", ""field2"": 2 }", +log_line,log_part,log_time,log_idle_msecs,log_level,log_mark,log_comment,log_tags,log_filters,arr,obj,lvl,user +0,,2013-09-06 20:00:48.124,0,trace,0,,,,,,TRACE, +2,,2013-09-06 20:00:49.124,1000,info,0,,,,,,INFO, +4,,2013-09-06 22:00:49.124,7200000,info,0,,,,,,INFO,steve@example.com +7,,2013-09-06 22:00:59.124,10000,debug5,0,,,,,,DEBUG5, +9,,2013-09-06 22:00:59.124,0,debug4,0,,,,,,DEBUG4, +11,,2013-09-06 22:00:59.124,0,debug3,0,,,,,,DEBUG3, +13,,2013-09-06 22:00:59.124,0,debug2,0,,,,,,DEBUG2, +15,,2013-09-06 22:00:59.124,0,debug,0,,,,,,DEBUG, +17,,2013-09-06 22:01:49.124,50000,stats,0,,,,,,STATS, +19,,2013-09-06 22:01:49.124,0,warning,0,,,,,,WARNING, +21,,2013-09-06 22:01:49.124,0,error,0,,,,,,ERROR, +23,,2013-09-06 22:01:49.124,0,critical,0,,,,,,CRITICAL, +25,,2013-09-06 22:01:49.124,0,fatal,0,,,,"[""hi"", {""sub1"": true}]","{ ""field1"" : ""hi"", ""field2"": 2 }",FATAL, diff --git a/test/expected/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.out b/test/expected/test_json_format.sh_8f2ebcd319afc7966ef11e31f9dd646bf6f001dd.out index 338bca95..caee6dd1 100644 --- 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 -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 +⋮ 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 +⋮ abc 49 def WARNING - not looking good +⋮ abc 49 def ERROR - looking bad +⋮ abc 49 def CRITICAL - sooo bad +⋮ abc 49 def FATAL - shoot  obj: { "field1" : "hi", "field2": 2 }  arr: ["hi", {"sub1": true}] diff --git a/test/expected/test_json_format.sh_989e52d167582648b73c5d025cc0e814c642b3c8.out b/test/expected/test_json_format.sh_989e52d167582648b73c5d025cc0e814c642b3c8.out index 55dcb761..2f9e1875 100644 --- 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 -2013-09-06T22:01:49.124 abc 49 def 10 c.e.foo looking bad +⋮ abc 49 def 10 c.e.foo looking bad diff --git a/test/expected/test_json_format.sh_a06b3cdd46b387e72d6faa4cce648b8b11ae870b.out b/test/expected/test_json_format.sh_a06b3cdd46b387e72d6faa4cce648b8b11ae870b.out index 6282d175..4d52fc4d 100644 --- 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 -[2013-09-06T22:01:49.124] WARNING not looking goodbork bork bork +[2013-09-06T22:01:49.124] ⋮ not looking goodbork bork bork -[2013-09-06T22:01:49.124] ERROR looking badbork bork bork +[2013-09-06T22:01:49.124] ⋮ looking badbork bork bork -[2013-09-06T22:01:49.124] CRITICAL sooo badbork bork bork +[2013-09-06T22:01:49.124] ⋮ sooo badbork bork bork diff --git a/test/formats/jsontest/format.json b/test/formats/jsontest/format.json index 78300e91..3a866bc6 100644 --- 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" } } } diff --git a/test/logfile_tcf.1 b/test/logfile_tcf.1 index c7c26992..eb1b565c 100644 --- 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 -TCF 01:11.475: 0: <--- R 2 ["P1"] +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 +TCF 01:11.475557: 0: <--- R 2 ["P1"] diff --git a/test/test_logfile.sh b/test/test_logfile.sh index 9ee9d524..7f2c01ed 100644 --- 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?" < C 2 RunControl getChildren null -TCF 2014-04-06 11:01:11.475000: 0: <--- R 2 ["P1"] +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 +TCF 2014-04-06 11:01:11.475557: 0: <--- R 2 ["P1"] EOF