tstack/lnav
1
1
Fork 0
mirror of https://github.com/tstack/lnav.git synced 2024-09-11 13:05:51 +03:00
Code Issues Projects Releases Wiki Activity

[json-log] fix some inconsistencies with json logs

Browse Source 
Fill some gaps brought up in #535
This commit is contained in:
Timothy Stack 2018-08-21 11:10:03 -07:00
parent 00baf0a1d9
commit b1ff6b3a3b
13 changed files with 179 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
NEWS
View File

@ -25,6 +25,11 @@ lnav v0.8.4:
* The relative time parser recognizes "next" at the beginning of the
input, for example, "next hour" or "next day". Handy for use in the
":goto" command.
* Added a "text-transform" option for formatting JSON log messages. The
supported options are: none, uppercase, lowercase, and capitalize.
* Added a special "__level__" field name for formatting JSON messages so
that the lnav level name can be used instead of the internal value in
the JSON object.
Interface Changes:
* When typing in a search, instead of moving the view to the first match
@ -42,6 +47,8 @@ lnav v0.8.4:
* Milliseconds can now be used in relative times (e.g. 10:00:00.123)
* The J/K hotkeys were not marking lines correctly when the bottom of
the view was reached.
* The level field in JSON logs should now be recognized by the level
patterns in the format.
lnav v0.8.3:
Features:

6
docs/source/formats.rst
View File

@ -81,7 +81,8 @@ fields:
:field: The name of the message field that should be inserted at this
point in the message. The special "__timestamp__" field name can be
used to insert a human-readable timestamp.
used to insert a human-readable timestamp. The "__level__" field can
be used to insert the level name as defined by lnav.
:min-width: The minimum width for the field. If the value for the field
in a given log message is shorter, padding will be added as needed to
meet the minimum-width requirement. (v0.8.2+)
@ -105,6 +106,8 @@ fields:
for this log message. (v0.8.2+)
:default-value: The default value to use if the field could not be found
in the current log message. The built-in default is "-".
:text-transform: Transform the text in the field. Supported options are:
none, uppercase, lowercase, capitalize
:timestamp-field: The name of the field that contains the log message
timestamp. Defaults to "timestamp".
@ -118,6 +121,7 @@ fields:
:%f: Microseconds as a decimal number (range 000000 to 999999).
:%N: Nanoseconds as a decimal number (range 000000000 to 999999999).
:%i: Milliseconds from the epoch.
:%6: Microseconds from the epoch.
:timestamp-divisor: For JSON logs with numeric timestamps, this value is used
to divide the timestamp by to get the number of seconds and fractional

43
src/default-log-formats.json
View File

@ -694,6 +694,49 @@
}
]
},
"journald_json_log" : {
"title" : "journalctl JSON log format",
"description" : "Logger format as created by systemd journalctl -o json",
"url" : "https://www.freedesktop.org/wiki/Software/systemd/json/",
"json" : true,
"hide-extra" : true,
"line-format" : [
{ "field" : "__timestamp__" },
" ",
{ "field" : "_SYSTEMD_UNIT" },
" ",
{ "field" : "SYSLOG_IDENTIFIER" },
"[",
{ "field" : "_PID" },
"] ",
{ "field" : "__level__", "text-transform": "uppercase" },
" ",
{ "field" : "MESSAGE" }
],
"timestamp-field": "__REALTIME_TIMESTAMP",
"timestamp-format": [
"%6"
],
"level-field" : "PRIORITY",
"level": {
"fatal" : "0",
"critical" : "2",
"error" : "3",
"warning" : "4",
"stats" : "5",
"info" : "6",
"debug" : "7"
},
"value": {
"__REALTIME_TIMESTAMP" : { "kind": "integer" },
"__MONOTONIC_TIMESTAMP" : { "kind": "integer", "hidden": true },
"_SYSTEMD_UNIT" : { "kind": "string", "identifier" : true },
"SYSLOG_IDENTIFIER" : { "kind": "string", "identifier" : true },
"_PID" : { "kind": "integer" },
"PRIORITY": { "kind": "string", "identifier" : true },
"MESSAGE": { "kind": "string", "identifier" : true }
}
},
"katello_log" : {
"title" : "Katello log format",
"description" : "Log format used by katello and foreman as used in Satellite 6.",

2
src/lnav.cc
View File

@ -3736,6 +3736,8 @@ int main(int argc, char *argv[])
looper();
signal(SIGINT, SIG_DFL);
save_session();
}
}

49
src/log_format.cc
View File

@ -549,6 +549,10 @@ log_format::scan_result_t external_log_format::scan(nonstd::optional<logfile *>
jlu.jlu_handle = handle;
if (yajl_parse(handle, line_data, sbr.length()) == yajl_status_ok &&
yajl_complete_parse(handle) == yajl_status_ok) {
if (ll.get_time() == 0) {
return log_format::SCAN_NO_MATCH;
}
for (int lpc = 0; lpc < jlu.jlu_sub_line_count; lpc++) {
ll.set_sub_offset(lpc);
if (lpc > 0) {
@ -914,11 +918,15 @@ static int read_json_field(yajlpp_parse_context *ypc, const unsigned char *str,
if (jlu->jlu_format->lf_timestamp_field == field_name) {
jlu->jlu_format->lf_date_time.scan((const char *)str, len, jlu->jlu_format->get_timestamp_formats(), &tm_out, tv_out);
jlu->jlu_format->lf_timestamp_flags = tm_out.et_flags;
// Leave off the machine oriented flag since we convert it anyhow
jlu->jlu_format->lf_timestamp_flags = tm_out.et_flags & ~ETF_MACHINE_ORIENTED;
jlu->jlu_base_line->set_time(tv_out);
}
else if (jlu->jlu_format->elf_level_field == field_name) {
jlu->jlu_base_line->set_level(abbrev2level((const char *)str, len));
pcre_input pi((const char *) str, 0, len);
pcre_context::capture_t level_cap = {0, (int) len};
jlu->jlu_base_line->set_level(jlu->jlu_format->convert_level(pi, &level_cap));
}
else if (jlu->jlu_format->elf_opid_field == field_name) {
uint8_t opid = hash_str((const char *) str, len);
@ -1048,6 +1056,8 @@ void external_log_format::get_subline(const logline &ll, shared_buffer_ref &sbr,
for (const auto &jfe : this->jlf_line_format) {
static const intern_string_t ts_field = intern_string::lookup("__timestamp__", -1);
static const intern_string_t level_field = intern_string::lookup("__level__");
size_t begin_size = this->jlf_cached_line.size();
switch (jfe.jfe_type) {
case JLF_CONSTANT:
@ -1147,14 +1157,42 @@ void external_log_format::get_subline(const logline &ll, shared_buffer_ref &sbr,
lv_iter = find_if(this->jlf_line_values.begin(),
this->jlf_line_values.end(),
logline_value_cmp(&this->lf_timestamp_field));
used_values[distance(this->jlf_line_values.begin(),
lv_iter)] = true;
if (lv_iter != this->jlf_line_values.end()) {
used_values[distance(this->jlf_line_values.begin(),
lv_iter)] = true;
}
}
else if (jfe.jfe_value == level_field) {
this->json_append(jfe, ll.get_level_name(), -1);
}
else {
this->json_append(jfe,
jfe.jfe_default_value.c_str(),
jfe.jfe_default_value.size());
}
switch (jfe.jfe_text_transform) {
case external_log_format::json_format_element::transform_t::NONE:
break;
case external_log_format::json_format_element::transform_t::UPPERCASE:
for (size_t cindex = begin_size; cindex < this->jlf_cached_line.size(); cindex++) {
this->jlf_cached_line[cindex] = toupper(this->jlf_cached_line[cindex]);
}
break;
case external_log_format::json_format_element::transform_t::LOWERCASE:
for (size_t cindex = begin_size; cindex < this->jlf_cached_line.size(); cindex++) {
this->jlf_cached_line[cindex] = tolower(this->jlf_cached_line[cindex]);
}
break;
case external_log_format::json_format_element::transform_t::CAPITALIZE:
for (size_t cindex = begin_size; cindex < begin_size + 1; cindex++) {
this->jlf_cached_line[cindex] = toupper(this->jlf_cached_line[cindex]);
}
for (size_t cindex = begin_size + 1; cindex < this->jlf_cached_line.size(); cindex++) {
this->jlf_cached_line[cindex] = tolower(this->jlf_cached_line[cindex]);
}
break;
}
break;
}
}
@ -1617,6 +1655,7 @@ void external_log_format::build(std::vector<std::string> &errors) {
iter != this->jlf_line_format.end();
++iter, format_index++) {
static const intern_string_t ts = intern_string::lookup("__timestamp__");
static const intern_string_t level_field = intern_string::lookup("__level__");
json_format_element &jfe = *iter;
if (jfe.jfe_value.empty() && !jfe.jfe_ts_format.empty()) {
@ -1628,6 +1667,8 @@ void external_log_format::build(std::vector<std::string> &errors) {
auto vd_iter = this->elf_value_defs.find(jfe.jfe_value);
if (jfe.jfe_value == ts) {
this->elf_value_defs[this->lf_timestamp_field]->vd_hidden = true;
} else if (jfe.jfe_value == level_field) {
this->elf_value_defs[this->elf_level_field]->vd_hidden = true;
} else if (vd_iter == this->elf_value_defs.end()) {
char index_str[32];

17
src/log_format.hh
View File

@ -1041,10 +1041,18 @@ public:
DOTDOT,
};
enum class transform_t {
NONE,
UPPERCASE,
LOWERCASE,
CAPITALIZE,
};
json_format_element()
: jfe_type(JLF_CONSTANT), jfe_default_value("-"), jfe_min_width(0),
jfe_max_width(LLONG_MAX), jfe_align(align_t::LEFT),
jfe_overflow(overflow_t::ABBREV)
jfe_overflow(overflow_t::ABBREV),
jfe_text_transform(transform_t::NONE)
{ };
json_log_field jfe_type;
@ -1054,6 +1062,7 @@ public:
long long jfe_max_width;
align_t jfe_align;
overflow_t jfe_overflow;
transform_t jfe_text_transform;
std::string jfe_ts_format;
};
@ -1192,6 +1201,9 @@ public:
void json_append_to_cache(const char *value, ssize_t len) {
size_t old_size = this->jlf_cached_line.size();
if (len == -1) {
len = strlen(value);
}
this->jlf_cached_line.resize(old_size + len);
memcpy(&(this->jlf_cached_line.data()[old_size]), value, len);
};
@ -1203,6 +1215,9 @@ public:
};
void json_append(const json_format_element &jfe, const char *value, ssize_t len) {
if (len == -1) {
len = strlen(value);
}
if (jfe.jfe_align == json_format_element::align_t::RIGHT) {
if (len < jfe.jfe_min_width) {
this->json_append_to_cache(jfe.jfe_min_width - len);

15
src/log_format_loader.cc
View File

@ -379,6 +379,15 @@ static const json_path_handler_base::enum_value_t OVERFLOW_ENUM[] = {
json_path_handler_base::ENUM_TERMINATOR
};
static const json_path_handler_base::enum_value_t TRANSFORM_ENUM[] = {
{ "none", external_log_format::json_format_element::transform_t::NONE },
{ "uppercase", external_log_format::json_format_element::transform_t::UPPERCASE },
{ "lowercase", external_log_format::json_format_element::transform_t::LOWERCASE },
{ "capitalize", external_log_format::json_format_element::transform_t::CAPITALIZE },
json_path_handler_base::ENUM_TERMINATOR
};
static struct json_path_handler line_format_handlers[] = {
json_path_handler("field")
.with_synopsis("<field-name>")
@ -421,6 +430,12 @@ static struct json_path_handler line_format_handlers[] = {
.with_enum_values(OVERFLOW_ENUM)
.FOR_FIELD(external_log_format::json_format_element, jfe_overflow),
json_path_handler("text-transform")
.with_synopsis("none|uppercase|lowercase|capitalize")
.with_description("Text transformation")
.with_enum_values(TRANSFORM_ENUM)
.FOR_FIELD(external_log_format::json_format_element, jfe_text_transform),
json_path_handler()
};

4
src/logfile_sub_source.hh
View File

@ -185,7 +185,7 @@ public:
bool get_max_log_time(struct timeval &tv_out) const {
tv_out = this->lss_max_log_time;
return (this->lss_max_log_time.tv_sec != INT_MAX ||
return (this->lss_max_log_time.tv_sec != std::numeric_limits<time_t>::max() ||
this->lss_max_log_time.tv_usec != 0);
};
@ -198,7 +198,7 @@ public:
void clear_min_max_log_times() {
memset(&this->lss_min_log_time, 0, sizeof(this->lss_min_log_time));
this->lss_max_log_time.tv_sec = INT_MAX;
this->lss_max_log_time.tv_sec = std::numeric_limits<time_t>::max();
this->lss_max_log_time.tv_usec = 0;
this->lss_force_rebuild = true;
};

30
src/ptimec.hh
View File

@ -439,6 +439,36 @@ inline void ftime_i(char *dst, off_t &off_inout, ssize_t len, const struct exttm
off_inout = strlen(dst);
}
#include "lnav_log.hh"
inline bool ptime_6(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len)
{
uint64_t epoch_us = 0;
time_t epoch;
while (off_inout < len && isdigit(str[off_inout])) {
epoch_us *= 10;
epoch_us += str[off_inout] - '0';
off_inout += 1;
}
dst->et_nsec = (epoch_us % 1000000ULL) * 1000ULL;
epoch = (epoch_us / 1000000ULL);
secs2tm(&epoch, &dst->et_tm);
dst->et_flags = ETF_DAY_SET|ETF_MONTH_SET|ETF_YEAR_SET|ETF_MACHINE_ORIENTED|ETF_EPOCH_TIME;
return (epoch_us > 0);
}
inline void ftime_6(char *dst, off_t &off_inout, ssize_t len, const struct exttm &tm)
{
int64_t t = tm2sec(&tm.et_tm);
t += tm.et_nsec / 1000;
snprintf(&dst[off_inout], len - off_inout, "%" PRId64, t);
off_inout = strlen(dst);
}
inline bool ptime_I(struct exttm *dst, const char *str, off_t &off_inout, ssize_t len)
{
PTIME_CONSUME(2, {

2
src/ptimec_rt.cc
View File

@ -82,6 +82,7 @@ bool ptime_fmt(const char *fmt, struct exttm *dst, const char *str, off_t &off,
FMT_CASE('M', M);
FMT_CASE('H', H);
FMT_CASE('i', i);
FMT_CASE('6', 6);
FMT_CASE('I', I);
FMT_CASE('d', d);
FMT_CASE('e', e);
@ -129,6 +130,7 @@ size_t ftime_fmt(char *dst, size_t len, const char *fmt, const struct exttm &tm)
FTIME_FMT_CASE('M', M);
FTIME_FMT_CASE('H', H);
FTIME_FMT_CASE('i', i);
FTIME_FMT_CASE('6', 6);
FTIME_FMT_CASE('I', I);
FTIME_FMT_CASE('d', d);
FTIME_FMT_CASE('e', e);

2
src/session_data.cc
View File

@ -1422,12 +1422,12 @@ void save_session(void)
char min_time_str[32], max_time_str[32];
sql_strftime(min_time_str, sizeof(min_time_str), min_time);
sql_strftime(max_time_str, sizeof(max_time_str), max_time);
if (have_min_time) {
cmd_array.gen("hide-lines-before "
+ string(min_time_str));
}
if (have_max_time) {
sql_strftime(max_time_str, sizeof(max_time_str), max_time);
cmd_array.gen("hide-lines-after "
+ string(max_time_str));
}

2
test/logfile_journald.json Normal file
View File

@ -0,0 +1,2 @@
{ "__CURSOR" : "s=e991dd5775894620914f2f7126aae6c1;i=372a;b=0dc874d3fbd44bdbb6fbcfaa27481492;m=24ea327;t=573f280a663fd;x=9ceeb77ef4331563", "__REALTIME_TIMESTAMP" : "1534860261221373", "__MONOTONIC_TIMESTAMP" : "38708007", "_BOOT_ID" : "0dc874d3fbd44bdbb6fbcfaa27481492", "PRIORITY" : "6", "_MACHINE_ID" : "1234567890abcdef1234567890abcdef", "_HOSTNAME" : "imx6ul-medusa", "SYSLOG_FACILITY" : "3", "_UID" : "0", "_GID" : "0", "_SYSTEMD_SLICE" : "system.slice", "_CAP_EFFECTIVE" : "3fffffffff", "_TRANSPORT" : "stdout", "_STREAM_ID" : "d6422e98dfb24d128e274f917f04362f", "SYSLOG_IDENTIFIER" : "python", "_PID" : "184", "_COMM" : "python", "_EXE" : "/usr/bin/python2.7", "_CMDLINE" : "/usr/bin/python -u /usr/bin/medusa/GpsLocator/GpsLocator.py", "_SYSTEMD_CGROUP" : "/system.slice/medusa-GpsLocator.service", "_SYSTEMD_UNIT" : "medusa-GpsLocator.service", "_SYSTEMD_INVOCATION_ID" : "e8fb03c1b8bf47b8ac2fc82f9870fd57", "MESSAGE" : "GPS Reference longitude: 7.358143333" }
{ "__CURSOR" : "s=e991dd5775894620914f2f7126aae6c1;i=372b;b=0dc874d3fbd44bdbb6fbcfaa27481492;m=24ea327;t=573f280a663fd;x=26df66509c108970", "__REALTIME_TIMESTAMP" : "1534860261221373", "__MONOTONIC_TIMESTAMP" : "38708007", "_BOOT_ID" : "0dc874d3fbd44bdbb6fbcfaa27481492", "PRIORITY" : "6", "_MACHINE_ID" : "1234567890abcdef1234567890abcdef", "_HOSTNAME" : "imx6ul-medusa", "SYSLOG_FACILITY" : "3", "_UID" : "0", "_GID" : "0", "_SYSTEMD_SLICE" : "system.slice", "_CAP_EFFECTIVE" : "3fffffffff", "_TRANSPORT" : "stdout", "_STREAM_ID" : "d6422e98dfb24d128e274f917f04362f", "SYSLOG_IDENTIFIER" : "python", "_PID" : "184", "_COMM" : "python", "_EXE" : "/usr/bin/python2.7", "_CMDLINE" : "/usr/bin/python -u /usr/bin/medusa/GpsLocator/GpsLocator.py", "_SYSTEMD_CGROUP" : "/system.slice/medusa-GpsLocator.service", "_SYSTEMD_UNIT" : "medusa-GpsLocator.service", "_SYSTEMD_INVOCATION_ID" : "e8fb03c1b8bf47b8ac2fc82f9870fd57", "MESSAGE" : "GPS Reference latitude: 46.908706667" }

9
test/test_json_format.sh
View File

@ -2,6 +2,15 @@
lnav_test="${top_builddir}/src/lnav-test"
run_test ${lnav_test} -n \
-I ${test_dir} \
${test_dir}/logfile_journald.json
check_output "journald json log format is not working" <<EOF
2018-08-21T07:04:21.221 medusa-GpsLocator.service python[184] INFO GPS Reference longitude: 7.358143333
2018-08-21T07:04:21.221 medusa-GpsLocator.service python[184] INFO GPS Reference latitude: 46.908706667
EOF
run_test ${lnav_test} -n \
-I ${test_dir} \