Skip to content

Commit 80ae6dc

Browse files
tstacktstack
committed
[log_format] display an error if there is a JSON timestamp property, but it does not parse correctly
1 parent e5135c5 commit 80ae6dc

12 files changed

+117
-34
lines changed

‎src/lnav.management_cli.cc‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -666,6 +666,16 @@ struct subcmd_format_t {
666666
retval.emplace_back(um);
667667
}
668668
},
669+
[&retval, &sample](const log_format::scan_error& se) {
670+
if (retval.empty()) {
671+
auto um = lnav::console::user_message::error(
672+
attr_line_t("test file did not match due to an error"));
673+
um.with_reason(se.se_message)
674+
.with_snippet(lnav::console::snippet::from(
675+
sample.s_line.pp_location, sample.s_line.pp_value));
676+
retval.emplace_back(um);
677+
}
678+
},
669679
[&retval, &sample](const log_format::scan_match& yep) mutable {
670680
auto al = attr_line_t("test file matched format");
671681
if (!sample.s_matched_regexes.empty()) {

‎src/log_format.cc‎

Lines changed: 38 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,7 @@
6767

6868
using namespace lnav::roles::literals;
6969
using namespace std::chrono_literals;
70+
using std::string_literals::operator""s;
7071

7172
static auto intern_lifetime = intern_string::get_table_lifetime();
7273

@@ -1150,6 +1151,7 @@ struct json_log_userdata {
11501151
std::optional<string_fragment> jlu_tid_frag;
11511152
std::optional<int64_t> jlu_tid_number;
11521153
std::optional<std::string> jlu_subid;
1154+
std::optional<log_format::scan_error> jlu_scan_error;
11531155
hasher jlu_opid_hasher;
11541156
std::chrono::microseconds jlu_duration{0};
11551157
exttm jlu_exttm;
@@ -1614,7 +1616,9 @@ external_log_format::scan_json(std::vector<logline>& dst,
16141616
return scan_no_match{"line is not a JSON object"};
16151617
}
16161618

1617-
ll.set_time(dst.back().get_time<std::chrono::microseconds>());
1619+
if (!dst.empty()) {
1620+
ll.set_time(dst.back().get_time<std::chrono::microseconds>());
1621+
}
16181622
ll.set_level(LEVEL_INVALID);
16191623
dst.emplace_back(ll);
16201624
return scan_match{0};
@@ -1659,6 +1663,18 @@ external_log_format::scan_json(std::vector<logline>& dst,
16591663
if (yajl_parse(handle, line_data, sbr.length()) == yajl_status_ok
16601664
&& yajl_complete_parse(handle) == yajl_status_ok)
16611665
{
1666+
if (jlu.jlu_scan_error) {
1667+
if (this->lf_specialized) {
1668+
if (!dst.empty()) {
1669+
ll.set_time(
1670+
dst.back().get_time<std::chrono::microseconds>());
1671+
}
1672+
ll.set_level(LEVEL_INVALID);
1673+
dst.emplace_back(ll);
1674+
return scan_match{0};
1675+
}
1676+
return jlu.jlu_scan_error.value();
1677+
}
16621678
if (ll.get_time<std::chrono::microseconds>().count() == 0) {
16631679
if (this->lf_specialized) {
16641680
if (!dst.empty()) {
@@ -2532,6 +2548,11 @@ read_json_field(yajlpp_parse_context* ypc,
25322548
if (last != nullptr) {
25332549
jlu->jlu_format->lf_timestamp_flags = jlu->jlu_exttm.et_flags;
25342550
jlu->jlu_base_line->set_time(tv_out);
2551+
} else {
2552+
jlu->jlu_scan_error = log_format::scan_error{fmt::format(
2553+
"failed to parse timestamp '{}' in string property '{}'",
2554+
frag,
2555+
field_name)};
25352556
}
25362557
} else if (jlu->jlu_format->elf_level_pointer.pp_value != nullptr) {
25372558
if (jlu->jlu_format->elf_level_pointer.pp_value
@@ -2636,6 +2657,7 @@ rewrite_json_field(yajlpp_parse_context* ypc,
26362657

26372658
// TODO add a timeval kind to logline_value
26382659
if (jlu->jlu_line->is_time_skewed()
2660+
|| jlu->jlu_line->get_msg_level() == LEVEL_INVALID
26392661
|| (jlu->jlu_format->lf_timestamp_flags
26402662
& (ETF_MICROS_SET | ETF_NANOS_SET | ETF_ZONE_SET)))
26412663
{
@@ -2658,6 +2680,11 @@ rewrite_json_field(yajlpp_parse_context* ypc,
26582680
== nullptr)
26592681
{
26602682
jlu->jlu_format->lf_date_time.relock(ls);
2683+
jlu->jlu_scan_error = log_format::scan_error{
2684+
fmt::format("failed to parse timestamp '{}' in string "
2685+
"property '{}'",
2686+
frag,
2687+
field_name)};
26612688
}
26622689
}
26632690
if (!jlu->jlu_subline_opts.hash_hack) {
@@ -2791,7 +2818,8 @@ external_log_format::get_subline(const log_format_file_state& lffs,
27912818
yajl_status parse_status = yajl_parse(
27922819
handle, (const unsigned char*) sbr.get_data(), sbr.length());
27932820
if (parse_status != yajl_status_ok
2794-
|| yajl_complete_parse(handle) != yajl_status_ok)
2821+
|| yajl_complete_parse(handle) != yajl_status_ok
2822+
|| jlu.jlu_scan_error)
27952823
{
27962824
unsigned char* msg;
27972825
std::string full_msg;
@@ -2813,7 +2841,9 @@ external_log_format::get_subline(const log_format_file_state& lffs,
28132841
this->jlf_line_values.clear();
28142842
this->jlf_line_attrs.emplace_back(
28152843
line_range{0, -1},
2816-
SA_INVALID.value("JSON line failed to parse"));
2844+
SA_INVALID.value(jlu.jlu_scan_error
2845+
? jlu.jlu_scan_error->se_message
2846+
: "JSON line failed to parse"));
28172847
} else {
28182848
std::vector<logline_value>::iterator lv_iter;
28192849
bool used_values[this->jlf_line_values.lvv_values.size()];
@@ -3022,8 +3052,7 @@ external_log_format::get_subline(const log_format_file_state& lffs,
30223052
lv_iter->lv_sub_offset = sub_offset;
30233053
used_values[std::distance(
30243054
this->jlf_line_values.lvv_values.begin(),
3025-
lv_iter)]
3026-
= true;
3055+
lv_iter)] = true;
30273056

30283057
if (!jfe.jfe_suffix.empty()) {
30293058
this->json_append_to_cache(jfe.jfe_suffix);
@@ -3069,8 +3098,7 @@ external_log_format::get_subline(const log_format_file_state& lffs,
30693098
{
30703099
used_values[distance(
30713100
this->jlf_line_values.lvv_values.begin(),
3072-
lv_iter)]
3073-
= true;
3101+
lv_iter)] = true;
30743102
}
30753103
if (!jfe.jfe_suffix.empty()) {
30763104
this->json_append_to_cache(jfe.jfe_suffix);
@@ -4365,8 +4393,7 @@ external_log_format::build(std::vector<lnav::console::user_message>& errors)
43654393
if (this->elf_type == elf_type_t::ELF_TYPE_JSON) {
43664394
for (const auto& vd : this->elf_value_def_order) {
43674395
this->elf_value_def_frag_map[vd->vd_meta.lvm_name
4368-
.to_string_fragment()]
4369-
= vd.get();
4396+
.to_string_fragment()] = vd.get();
43704397
}
43714398
}
43724399

@@ -4607,12 +4634,10 @@ external_log_format::build(std::vector<lnav::console::user_message>& errors)
46074634
= this->elf_value_defs.find(jfe.jfe_value.pp_value);
46084635
if (jfe.jfe_value.pp_value == ts) {
46094636
this->elf_value_defs[this->lf_timestamp_field]
4610-
->vd_meta.lvm_hidden
4611-
= true;
4637+
->vd_meta.lvm_hidden = true;
46124638
} else if (jfe.jfe_value.pp_value == level_field) {
46134639
this->elf_value_defs[this->elf_level_field]
4614-
->vd_meta.lvm_hidden
4615-
= true;
4640+
->vd_meta.lvm_hidden = true;
46164641
} else if (vd_iter == this->elf_value_defs.end()) {
46174642
errors.emplace_back(
46184643
lnav::console::user_message::error(

‎src/log_format.hh‎

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -163,14 +163,18 @@ public:
163163
uint32_t sm_strikes{0};
164164
};
165165

166+
struct scan_error {
167+
std::string se_message;
168+
};
169+
166170
struct scan_no_match {
167171
const char* snm_reason{nullptr};
168172
};
169173

170174
struct scan_incomplete {};
171175

172-
using scan_result_t
173-
= mapbox::util::variant<scan_match, scan_no_match, scan_incomplete>;
176+
using scan_result_t = mapbox::util::
177+
variant<scan_match, scan_no_match, scan_error, scan_incomplete>;
174178

175179
virtual scan_result_t test_line(
176180
sample_t& sample, std::vector<lnav::console::user_message>& msgs);
@@ -188,8 +192,7 @@ public:
188192
std::vector<logline>& dst,
189193
const line_info& li,
190194
shared_buffer_ref& sbr,
191-
scan_batch_context& sbc)
192-
= 0;
195+
scan_batch_context& sbc) = 0;
193196

194197
virtual bool scan_for_partial(const log_format_file_state& lffs,
195198
shared_buffer_ref& sbr,

‎src/logfile.cc‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1020,6 +1020,26 @@ logfile::process_prefix(shared_buffer_ref& sbr,
10201020
"more data required",
10211021
curr->get_name().c_str());
10221022
},
1023+
[this, curr](const log_format::scan_error& se) {
1024+
this->lf_invalid_lines.ili_total += 1;
1025+
if (this->lf_invalid_lines.ili_lines.size()
1026+
>= invalid_line_info::MAX_INVALID_LINES)
1027+
{
1028+
return;
1029+
}
1030+
this->lf_invalid_lines.ili_lines.emplace_back(
1031+
this->lf_index.size());
1032+
this->lf_format_match_messages.emplace_back(
1033+
lnav::console::user_message::error(
1034+
attr_line_t()
1035+
.append(lnav::roles::identifier(
1036+
curr->get_name().to_string()))
1037+
.append(" failed to scan line ")
1038+
.append(lnav::roles::number(
1039+
fmt::to_string(this->lf_index.size())))
1040+
.append(": ")
1041+
.append(se.se_message)));
1042+
},
10231043
[this, curr, prescan_size](
10241044
const log_format::scan_no_match& snm) {
10251045
if (this->lf_format == nullptr && prescan_size < 5) {

‎test/expected/test_json_format.sh_168cac40c27f547044c89d39eb0ff2ef81da4b21.out‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33
{"ts": "2013-09-06T22:00:49.124817Z", "lvl": "INFO", "msg": "Shutting down service", "user": "steve@example.com"}
44
{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG5", "msg": "D\bDetails...\n"}
55
{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG4", "msg": "D\bDe\betails...\n"}
6+
{"ts": "xxx", "lvl": "DEBUG3", "msg": "bad ts...\n"}
67
{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG3", "msg": "Details...\n"}
78
{"ts": "2013-09-06T22:00:59.124817Z", "lvl": "DEBUG2", "msg": "Details...\n"}
89
{"ts": "2013-09-06 22:01:00Z", "lvl": "DEBUG", "msg": "Details..."}

‎test/expected/test_json_format.sh_40223ac4742883f883ccc61044bfffd6e102cca6.out‎

Lines changed: 24 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -87,6 +87,23 @@
8787
{
8888
"log_line": 11,
8989
"log_time": "2013-09-06 22:00:59.124817",
90+
"log_level": "invalid",
91+
"arr": null,
92+
"obj": null,
93+
"logger": null,
94+
"lvl": null,
95+
"user": null,
96+
"log_part": null,
97+
"log_idle_msecs": 0,
98+
"log_mark": 0,
99+
"log_comment": null,
100+
"log_tags": null,
101+
"log_annotations": null,
102+
"log_filters": null
103+
},
104+
{
105+
"log_line": 12,
106+
"log_time": "2013-09-06 22:00:59.124817",
90107
"log_level": "debug3",
91108
"arr": null,
92109
"obj": null,
@@ -102,7 +119,7 @@
102119
"log_filters": null
103120
},
104121
{
105-
"log_line": 13,
122+
"log_line": 14,
106123
"log_time": "2013-09-06 22:00:59.124817",
107124
"log_level": "debug2",
108125
"arr": null,
@@ -119,7 +136,7 @@
119136
"log_filters": null
120137
},
121138
{
122-
"log_line": 15,
139+
"log_line": 16,
123140
"log_time": "2013-09-06 22:01:00.000000",
124141
"log_level": "debug",
125142
"arr": null,
@@ -136,7 +153,7 @@
136153
"log_filters": null
137154
},
138155
{
139-
"log_line": 17,
156+
"log_line": 18,
140157
"log_time": "2013-09-06 22:01:49.124817",
141158
"log_level": "stats",
142159
"arr": null,
@@ -153,7 +170,7 @@
153170
"log_filters": null
154171
},
155172
{
156-
"log_line": 19,
173+
"log_line": 20,
157174
"log_time": "2013-09-06 22:01:49.124817",
158175
"log_level": "warning",
159176
"arr": null,
@@ -170,7 +187,7 @@
170187
"log_filters": null
171188
},
172189
{
173-
"log_line": 21,
190+
"log_line": 22,
174191
"log_time": "2013-09-06 22:01:49.124817",
175192
"log_level": "error",
176193
"arr": null,
@@ -187,7 +204,7 @@
187204
"log_filters": null
188205
},
189206
{
190-
"log_line": 23,
207+
"log_line": 24,
191208
"log_time": "2013-09-06 22:01:49.124817",
192209
"log_level": "critical",
193210
"arr": null,
@@ -204,7 +221,7 @@
204221
"log_filters": null
205222
},
206223
{
207-
"log_line": 25,
224+
"log_line": 26,
208225
"log_time": "2013-09-06 22:01:49.124817",
209226
"log_level": "fatal",
210227
"arr": [

‎test/expected/test_json_format.sh_469f005b0708d629bc95f0c48a5e390f440c1fef.out‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
[2013-09-06T22:00:59.124817Z] ⋮ Details...
1010

1111
[2013-09-06T22:00:59.124817Z] ⋮ Details...
12+
[offset: 531] {"ts": "xxx", "lvl": "DEBUG3", "msg": "bad ts...\n"}
1213

1314
[2013-09-06T22:00:59.124817Z] ⋮ Details...
1415

‎test/expected/test_json_format.sh_85d03b1b41a7f819af135d2521a8f2c59418e907.out‎

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -4,11 +4,12 @@ log_line,log_time,log_level,arr,obj,logger,lvl,user,log_part,log_idle_msecs,log_
44
4,2013-09-06 22:00:49.124817,info,<NULL>,<NULL>,<NULL>,INFO,steve@example.com,<NULL>,7200000,0,<NULL>,<NULL>,<NULL>,<NULL>
55
7,2013-09-06 22:00:59.124817,debug5,<NULL>,<NULL>,<NULL>,DEBUG5,<NULL>,<NULL>,10000,0,<NULL>,<NULL>,<NULL>,<NULL>
66
9,2013-09-06 22:00:59.124817,debug4,<NULL>,<NULL>,<NULL>,DEBUG4,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
7-
11,2013-09-06 22:00:59.124817,debug3,<NULL>,<NULL>,<NULL>,DEBUG3,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
8-
13,2013-09-06 22:00:59.124817,debug2,<NULL>,<NULL>,<NULL>,DEBUG2,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
9-
15,2013-09-06 22:01:00.000000,debug,<NULL>,<NULL>,<NULL>,DEBUG,<NULL>,<NULL>,876,0,<NULL>,<NULL>,<NULL>,<NULL>
10-
17,2013-09-06 22:01:49.124817,stats,<NULL>,<NULL>,<NULL>,STATS,<NULL>,<NULL>,49124,0,<NULL>,<NULL>,<NULL>,<NULL>
11-
19,2013-09-06 22:01:49.124817,warning,<NULL>,<NULL>,<NULL>,WARNING,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
12-
21,2013-09-06 22:01:49.124817,error,<NULL>,<NULL>,<NULL>,ERROR,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
13-
23,2013-09-06 22:01:49.124817,critical,<NULL>,<NULL>,<NULL>,CRITICAL,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
14-
25,2013-09-06 22:01:49.124817,fatal,"[""hi"", {""sub1"": true}]","{ ""field1"" : ""hi"", ""field2"": 2 }",<NULL>,FATAL,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
7+
11,2013-09-06 22:00:59.124817,invalid,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
8+
12,2013-09-06 22:00:59.124817,debug3,<NULL>,<NULL>,<NULL>,DEBUG3,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
9+
14,2013-09-06 22:00:59.124817,debug2,<NULL>,<NULL>,<NULL>,DEBUG2,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
10+
16,2013-09-06 22:01:00.000000,debug,<NULL>,<NULL>,<NULL>,DEBUG,<NULL>,<NULL>,876,0,<NULL>,<NULL>,<NULL>,<NULL>
11+
18,2013-09-06 22:01:49.124817,stats,<NULL>,<NULL>,<NULL>,STATS,<NULL>,<NULL>,49124,0,<NULL>,<NULL>,<NULL>,<NULL>
12+
20,2013-09-06 22:01:49.124817,warning,<NULL>,<NULL>,<NULL>,WARNING,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
13+
22,2013-09-06 22:01:49.124817,error,<NULL>,<NULL>,<NULL>,ERROR,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
14+
24,2013-09-06 22:01:49.124817,critical,<NULL>,<NULL>,<NULL>,CRITICAL,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>
15+
26,2013-09-06 22:01:49.124817,fatal,"[""hi"", {""sub1"": true}]","{ ""field1"" : ""hi"", ""field2"": 2 }",<NULL>,FATAL,<NULL>,<NULL>,0,0,<NULL>,<NULL>,<NULL>,<NULL>

‎test/expected/test_json_format.sh_a06b3cdd46b387e72d6faa4cce648b8b11ae870b.out‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,10 @@ bork bork bork
1111

1212
[2013-09-06T22:00:59.124817Z] ⋮ Details...
1313
bork bork bork
14+
[offset: 531] {"ts": "xxx", "lvl": "DEBUG3", "msg": "bad ts...\n"}
15+
unknown error
16+
{"ts": "xxx", "lvl": "DEBUG3",
17+
(right here) ------^
1418

1519
[2013-09-06T22:00:59.124817Z] ⋮ Details...
1620
bork bork bork
@@ -25,5 +29,3 @@ bork bork bork
2529
[2013-09-06T22:01:49.124817Z] ⋮ not looking goodbork bork bork
2630
 
2731
[2013-09-06T22:01:49.124817Z] ⋮ looking badbork bork bork
28-
 
29-
[2013-09-06T22:01:49.124817Z] ⋮ sooo badbork bork bork

‎test/expected/test_json_format.sh_eb316389dd36295ceebfa23cf39727fa8314fa91.out‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
[2013-09-06T18:00:59.124817-0400] ⋮ Details...
1010

1111
[2013-09-06T18:00:59.124817-0400] ⋮ Details...
12+
[offset: 531] {"ts": "xxx", "lvl": "DEBUG3", "msg": "bad ts...\n"}
1213

1314
[2013-09-06T18:00:59.124817-0400] ⋮ Details...
1415

0 commit comments

Comments
 (0)