Archives/lnav
2
0
Fork 0
mirror of https://github.com/tstack/lnav synced 2024-11-01 21:40:34 +00:00
Code Issues Packages Projects Releases Wiki Activity

[ui] highlight out-of-time-order messages in yellow with an underline

Browse Source
This commit is contained in:
Timothy Stack 2016-03-03 06:05:26 -08:00
parent 32f022a333
commit 53e2d92eef
11 changed files with 143 additions and 10 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
NEWS
View File

@ -33,6 +33,14 @@ lnav v0.8.1:
moving forward and backward by 60 minutes can be simulated by
using the ':goto' command with a relative time and the 'r/R'
hotkeys.
* Log messages with timestamps that pre-date previous log messages will
have the timestamp highlighted in yellow and underlined. These out-
of-time-order messages will be assigned the time of the previous
message for sorting purposes. You can press the 'p' hotkey to examine
the 'Received Time' of the message as well as the time parsed from the
original message. A "log_actual_time" hidden field has also been
added to the SQLite virtual table so you can operate on the original
message time from the file.
Fixes:
* Issues with tailing JSON logs have been fixed.

53
src/field_overlay_source.cc
View File

@ -92,26 +92,63 @@ size_t field_overlay_source::list_overlay_count(const listview_curses &lv)
this->fos_lines.push_back(pattern_al);
}
char old_timestamp[64], curr_timestamp[64];
char old_timestamp[64], curr_timestamp[64], orig_timestamp[64];
struct timeval curr_tv, offset_tv, orig_tv;
char log_time[256];
attr_line_t time_line;
string &time_str = time_line.get_string();
struct line_range time_lr;
sql_strftime(curr_timestamp, sizeof(curr_timestamp),
this->fos_log_helper.ldh_line->get_time(),
this->fos_log_helper.ldh_line->get_millis(),
'T');
time_str = " Received Time: ";
time_lr.lr_start = time_str.length();
time_str.append(curr_timestamp);
time_lr.lr_end = time_str.length();
time_line.with_attr(string_attr(time_lr, &view_curses::VC_STYLE, A_BOLD));
struct line_range time_range = find_string_attr_range(
this->fos_log_helper.ldh_line_attrs, &logline::L_TIMESTAMP);
if (this->fos_log_helper.ldh_line->is_time_skewed() && time_range.lr_end != -1) {
const char *time_src = this->fos_log_helper.ldh_msg.get_data() +
time_range.lr_start;
struct timeval tv;
struct exttm tm;
if (lf->lf_date_time.scan(time_src, time_range.length(), NULL, &tm, tv)) {
time_lr.lr_start = time_str.length() + 2;
sql_strftime(orig_timestamp, sizeof(orig_timestamp), tv, 'T');
time_str.append(" Actual Time: ");
time_str.append(orig_timestamp);
time_lr.lr_end = time_str.length();
time_line.with_attr(string_attr(
time_lr,
&view_curses::VC_STYLE,
vc.attrs_for_role(view_colors::VCR_SKEWED_TIME)));
}
}
curr_tv = this->fos_log_helper.ldh_line->get_timeval();
offset_tv = this->fos_log_helper.ldh_file->get_time_offset();
timersub(&curr_tv, &offset_tv, &orig_tv);
sql_strftime(old_timestamp, sizeof(old_timestamp),
orig_tv.tv_sec, orig_tv.tv_usec / 1000,
'T');
snprintf(log_time, sizeof(log_time),
" Current Time: %s Original Time: %s Offset: %+d.%03d",
curr_timestamp,
old_timestamp,
(int)offset_tv.tv_sec, (int)(offset_tv.tv_usec / 1000));
this->fos_lines.push_back(log_time);
if (offset_tv.tv_sec || offset_tv.tv_usec) {
char offset_str[32];
time_str.append(" Pre-adjust Time: ");
time_str.append(old_timestamp);
snprintf(offset_str, sizeof(offset_str),
" Offset: %+d.%03d",
(int)offset_tv.tv_sec, (int)(offset_tv.tv_usec / 1000));
time_str.append(offset_str);
}
this->fos_lines.push_back(time_line);
if (this->fos_log_helper.ldh_line_values.empty()) {
this->fos_lines.push_back(" No known message fields");

6
src/log_data_helper.hh
View File

@ -63,6 +63,7 @@ public:
this->ldh_scanner.reset();
this->ldh_namer.reset();
this->ldh_json_pairs.clear();
this->ldh_line_attrs.clear();
};
bool parse_line(vis_line_t line, bool allow_middle = false) {
@ -88,12 +89,14 @@ public:
this->ldh_scanner.reset();
this->ldh_namer.reset();
this->ldh_json_pairs.clear();
this->ldh_line_attrs.clear();
}
else {
log_format *format = this->ldh_file->get_format();
struct line_range body;
string_attrs_t sa;
string_attrs_t &sa = this->ldh_line_attrs;
this->ldh_line_attrs.clear();
this->ldh_line_values.clear();
this->ldh_file->read_full_message(ll, this->ldh_msg);
format->annotate(this->ldh_msg, sa, this->ldh_line_values);
@ -191,6 +194,7 @@ public:
std::auto_ptr<data_scanner> ldh_scanner;
std::auto_ptr<data_parser> ldh_parser;
std::auto_ptr<column_namer> ldh_namer;
string_attrs_t ldh_line_attrs;
std::vector<logline_value> ldh_line_values;
std::map<const intern_string_t, json_ptr_walk::walk_list_t> ldh_json_pairs;
};

20
src/log_format.hh
View File

@ -89,11 +89,16 @@ public:
LEVEL__MAX,
LEVEL_TIME_SKEW = 0x20, /*< Received after timestamp. */
LEVEL_MARK = 0x40, /*< Bookmarked line. */
LEVEL_CONTINUED = 0x80, /*< Continuation of multiline entry. */
/** Mask of flags for the level field. */
LEVEL__FLAGS = (LEVEL_MARK | LEVEL_CONTINUED)
LEVEL__FLAGS = (
LEVEL_TIME_SKEW |
LEVEL_MARK |
LEVEL_CONTINUED
)
} level_t;
static const char *level_names[LEVEL__MAX + 1];
@ -193,6 +198,19 @@ public:
bool is_marked(void) const { return this->ll_level & LEVEL_MARK; };
void set_time_skew(bool val) {
if (val) {
this->ll_level |= LEVEL_TIME_SKEW;
}
else {
this->ll_level &= ~LEVEL_TIME_SKEW;
}
};
bool is_time_skewed() const {
return this->ll_level & LEVEL_TIME_SKEW;
};
/** @param l The logging level. */
void set_level(level_t l) { this->ll_level = l; };

28
src/log_vtab_impl.cc
View File

@ -69,6 +69,7 @@ std::string log_vtab_impl::get_table_statement(void)
<< " log_line integer PRIMARY KEY,\n"
<< " log_part text collate naturalnocase,\n"
<< " log_time datetime,\n"
<< " log_actual_time datetime hidden,\n"
<< " log_idle_msecs int,\n"
<< " log_level text collate loglevel,\n"
<< " log_mark boolean,\n";
@ -296,6 +297,33 @@ static int vt_column(sqlite3_vtab_cursor *cur, sqlite3_context *ctx, int col)
}
break;
case VT_COL_LOG_ACTUAL_TIME: {
char buffer[64];
if (ll->is_time_skewed()) {
log_format *format = lf->get_format();
shared_buffer_ref line;
vector<logline> dst;
lf->read_line(ll, line);
switch (format->scan(dst, 0, line)) {
case log_format::SCAN_MATCH:
sql_strftime(buffer, sizeof(buffer),
dst.back().get_time(),
dst.back().get_millis());
break;
default:
buffer[0] = '\0';
break;
}
}
else {
sql_strftime(buffer, sizeof(buffer), ll->get_time(), ll->get_millis());
}
sqlite3_result_text(ctx, buffer, strlen(buffer), SQLITE_TRANSIENT);
break;
}
case VT_COL_IDLE_MSECS:
if (vc->log_cursor.lc_curr_line == 0) {
sqlite3_result_int64(ctx, 0);

1
src/log_vtab_impl.hh
View File

@ -43,6 +43,7 @@ enum {
VT_COL_LINE_NUMBER,
VT_COL_PARTITION,
VT_COL_LOG_TIME,
VT_COL_LOG_ACTUAL_TIME,
VT_COL_IDLE_MSECS,
VT_COL_LEVEL,
VT_COL_MARK,

2
src/logfile.cc
View File

@ -200,6 +200,8 @@ void logfile::process_prefix(off_t offset, shared_buffer_ref &sbr)
logline &latest = this->lf_index.back();
if (latest < second_to_last) {
log_debug("time skew! %d", this->lf_index.size());
latest.set_time_skew(true);
latest.set_time(second_to_last.get_time());
latest.set_millis(second_to_last.get_millis());
}

10
src/logfile_sub_source.cc
View File

@ -430,6 +430,16 @@ void logfile_sub_source::text_attrs_for_line(textview_curses &lv,
value_out.push_back(string_attr(time_range, &view_curses::VC_STYLE, attrs));
}
}
if (this->lss_token_line->is_time_skewed()) {
struct line_range time_range = find_string_attr_range(
value_out, &logline::L_TIMESTAMP);
if (time_range.lr_end != -1) {
attrs = vc.attrs_for_role(view_colors::VCR_SKEWED_TIME);
value_out.push_back(string_attr(time_range, &view_curses::VC_STYLE, attrs));
}
}
}
bool logfile_sub_source::rebuild_index(bool force)

1
src/view_curses.cc
View File

@ -309,6 +309,7 @@ void view_colors::init_roles(void)
this->vc_role_colors[VCR_WARNING] = ansi_color_pair(COLOR_YELLOW, COLOR_BLACK) | A_BOLD;
this->vc_role_colors[VCR_ALT_ROW] = ansi_color_pair(COLOR_WHITE, COLOR_BLACK) | A_BOLD;
this->vc_role_colors[VCR_ADJUSTED_TIME] = ansi_color_pair(COLOR_MAGENTA, COLOR_BLACK);
this->vc_role_colors[VCR_SKEWED_TIME] = ansi_color_pair(COLOR_YELLOW, COLOR_BLACK) | A_UNDERLINE;
this->vc_role_colors[VCR_STATUS] =
ansi_color_pair(COLOR_BLACK, COLOR_WHITE);

1
src/view_curses.hh
View File

@ -507,6 +507,7 @@ public:
VCR_WARNING, /*< A warning message. */
VCR_ALT_ROW, /*< Highlight for alternating rows in a list */
VCR_ADJUSTED_TIME,
VCR_SKEWED_TIME,
VCR_STATUS, /*< Normal status line text. */
VCR_WARN_STATUS,
VCR_ALERT_STATUS, /*< Alert status line text. */

23
test/test_sql.sh
View File

@ -3,6 +3,29 @@
lnav_test="${top_builddir}/src/lnav-test"
run_test ${lnav_test} -n \
-c ";select log_time,log_actual_time from syslog_log" \
-c ':write-csv-to -' \
${test_dir}/logfile_syslog_with_mixed_times.0
check_output "log_actual_time column not working" <<EOF
log_time,log_actual_time
2015-09-13 00:58:45.000,2015-09-13 00:58:45.000
2015-09-13 00:59:30.000,2015-09-13 00:59:30.000
2015-09-13 01:23:54.000,2015-09-13 01:23:54.000
2015-09-13 03:12:04.000,2015-09-13 03:12:04.000
2015-09-13 03:12:04.000,2015-09-13 03:12:04.000
2015-09-13 03:12:04.000,2015-09-13 01:25:39.000
2015-09-13 03:12:04.000,2015-09-13 03:12:04.000
2015-09-13 03:12:58.000,2015-09-13 03:12:58.000
2015-09-13 03:46:03.000,2015-09-13 03:46:03.000
2015-09-13 03:46:03.000,2015-09-13 03:46:03.000
2015-09-13 03:46:03.000,2015-09-13 03:46:03.000
2015-09-13 03:46:03.000,2015-09-13 03:13:16.000
2015-09-13 03:46:03.000,2015-09-13 03:46:03.000
EOF
run_test ${lnav_test} -n \
-c ";update access_log set log_part = 'middle' where log_line = 1" \
-c ';select * from access_log' \