[format] add more log levels and fix some more pretty-printer glitches

Fixes #212

NEWS

@@ -37,6 +37,7 @@ lnav v0.7.3:
        how each format matches each other formats sample lines.
      * Command files (i.e. those executed via the '-f' flag) now support
        commands/queries that span more than one line.
+     * Added more log levels: stats, debug2 - debug5.
 
 lnav v0.7.2:
      * Added log formats for vdsm, openstack, and the vmkernel.

TESTS_ENVIRONMENT.in

@@ -72,7 +72,7 @@ run_test() {
 #     EOF
 #
 check_output() {
-    diff -w -u ${test_file_base}_${test_num}.tmp - > ${test_file_base}_${test_num}.diff
+    diff -w -u - ${test_file_base}_${test_num}.tmp > ${test_file_base}_${test_num}.diff
     if test $? -ne 0; then
         echo $LAST_TEST
         echo $1
@@ -83,7 +83,7 @@ check_output() {
 }
 
 check_error_output() {
-    diff -w -u ${test_file_base}_${test_num}.err - \
+    diff -w -u - ${test_file_base}_${test_num}.err \
         > ${test_file_base}_${test_num}.err.diff
     if test $? -ne 0; then
         echo $LAST_TEST

docs/source/formats.rst

@@ -84,7 +84,7 @@ fields:
     checked against each of these regexes.  Once a match is found, the log
     message level will set to the corresponding level.  The available levels,
     in order of severity, are: **fatal**, **critical**, **error**,
-    **warning**, **info**, **debug**, **trace**.
+    **warning**, **stats**, **info**, **debug**, **debug2-5**, **trace**.
 
   :value: This object contains the definitions for the values captured by the
     regexes.

src/lnav.cc

@@ -1,5 +1,5 @@
 /**
- * Copyright (c) 2007-2012, Timothy Stack
+ * Copyright (c) 2007-2015, Timothy Stack
  *
  * All rights reserved.
  *
@@ -1237,7 +1237,7 @@ static void open_pretty_view(void)
             pretty_printer pp(&ds);
 
             // TODO: dump more details of the line in the output.
-            stream << pp.print() << endl;
+            stream << trim(pp.print()) << endl;
             first_line = false;
         }
         pretty_tc->set_sub_source(new plain_text_source(stream.str()));
@@ -1653,10 +1653,10 @@ static void handle_paging_key(int ch)
             HELP_MSG_1(c, "to copy marked lines to the clipboard; ")
             HELP_MSG_1(C, "to clear marked lines"));
 
-        user_top = next_cluster(&bookmark_vector<vis_line_t>::next, 
+        user_top = next_cluster(&bookmark_vector<vis_line_t>::next,
             &textview_curses::BM_USER,
             tc->get_top());
-        part_top = next_cluster(&bookmark_vector<vis_line_t>::next, 
+        part_top = next_cluster(&bookmark_vector<vis_line_t>::next,
             &textview_curses::BM_PARTITION,
             tc->get_top());
         if (part_top == -1 && user_top == -1) {
@@ -1677,10 +1677,10 @@ static void handle_paging_key(int ch)
     case 'U': {
         vis_line_t user_top, part_top;
 
-        user_top = next_cluster(&bookmark_vector<vis_line_t>::prev, 
+        user_top = next_cluster(&bookmark_vector<vis_line_t>::prev,
             &textview_curses::BM_USER,
             tc->get_top());
-        part_top = next_cluster(&bookmark_vector<vis_line_t>::prev, 
+        part_top = next_cluster(&bookmark_vector<vis_line_t>::prev,
             &textview_curses::BM_PARTITION,
             tc->get_top());
         if (part_top == -1 && user_top == -1) {

src/log_format.cc

@@ -66,8 +66,13 @@ string_attr_type logline::L_PARTITION;
 const char *logline::level_names[LEVEL__MAX + 1] = {
     "unknown",
     "trace",
+    "debug5",
+    "debug4",
+    "debug3",
+    "debug2",
     "debug",
     "info",
+    "stats",
     "warning",
     "error",
     "critical",
@@ -77,7 +82,7 @@ const char *logline::level_names[LEVEL__MAX + 1] = {
 };
 
 static pcrepp LEVEL_RE(
-        "(?i)(TRACE|VERBOSE|DEBUG|INFO|WARN(?:ING)?|ERROR|CRITICAL|SEVERE|FATAL)");
+        "^(?i)(TRACE|DEBUG\\d*|INFO|STATS|WARN(?:ING)?|ERROR|CRITICAL|SEVERE|FATAL)$");
 
 logline::level_t logline::string2level(const char *levelstr, ssize_t len, bool exact)
 {
@@ -113,15 +118,28 @@ logline::level_t logline::abbrev2level(const char *levelstr, ssize_t len)
             return LEVEL_TRACE;
         case 'D':
         case 'V':
+            if (len > 1) {
+                switch (levelstr[len - 1]) {
+                    case '2':
+                        return LEVEL_DEBUG2;
+                    case '3':
+                        return LEVEL_DEBUG3;
+                    case '4':
+                        return LEVEL_DEBUG4;
+                    case '5':
+                        return LEVEL_DEBUG5;
+                }
+            }
             return LEVEL_DEBUG;
         case 'I':
             return LEVEL_INFO;
+        case 'S':
+            return LEVEL_STATS;
         case 'W':
             return LEVEL_WARNING;
         case 'E':
             return LEVEL_ERROR;
         case 'C':
-        case 'S':
             return LEVEL_CRITICAL;
         case 'F':
             return LEVEL_FATAL;

src/log_format.hh

@@ -71,8 +71,13 @@ public:
     typedef enum {
         LEVEL_UNKNOWN,
         LEVEL_TRACE,
+        LEVEL_DEBUG5,
+        LEVEL_DEBUG4,
+        LEVEL_DEBUG3,
+        LEVEL_DEBUG2,
         LEVEL_DEBUG,
         LEVEL_INFO,
+        LEVEL_STATS,
         LEVEL_WARNING,
         LEVEL_ERROR,
         LEVEL_CRITICAL,
@@ -184,7 +189,7 @@ public:
 
     const char *get_level_name() const
     {
-        return level_names[this->ll_level & 0x0f];
+        return level_names[this->ll_level & ~LEVEL__FLAGS];
     };
 
     bool is_continued(void) const {

src/log_format_loader.cc

@@ -156,7 +156,8 @@ static int read_levels(yajlpp_parse_context *ypc, const unsigned char *str, size
 {
     external_log_format *elf = ensure_format(ypc);
     string regex = string((const char *)str, len);
-    logline::level_t level = logline::string2level(ypc->get_path_fragment(2).c_str());
+    string level_name_or_number = ypc->get_path_fragment(2);
+    logline::level_t level = logline::string2level(level_name_or_number.c_str());
 
     elf->elf_level_patterns[level].lp_regex = regex;
 
@@ -376,7 +377,7 @@ static struct json_path_handler format_handlers[] = {
     json_path_handler("^/\\w+/(file-pattern|level-field|timestamp-field|body-field|url|url#|title|description)$",
                       read_format_field),
     json_path_handler("^/\\w+/level/"
-                      "(trace|debug|info|warning|error|critical|fatal)$",
+                      "(trace|debug\\d*|info|stats|warning|error|critical|fatal)$",
                       read_levels),
     json_path_handler("^/\\w+/value/\\w+/(kind|collate|unit/field)$", read_value_def),
     json_path_handler("^/\\w+/value/\\w+/(identifier|foreign-key|hidden)$", read_value_bool),

src/pretty_printer.hh

@@ -87,12 +87,14 @@ public:
                     continue;
                 case DT_LCURLY:
                 case DT_LSQUARE:
+                case DT_LPAREN:
                     this->flush_values(true);
                     this->pp_values.push_back(el);
                     this->descend();
                     continue;
                 case DT_RCURLY:
                 case DT_RSQUARE:
+                case DT_RPAREN:
                     this->flush_values();
                     if (this->pp_body_lines.top()) {
                         this->start_new_line();
@@ -168,10 +170,15 @@ private:
     }
 
     void ascend() {
-        int lines = this->pp_body_lines.top();
+        if (this->pp_depth > 0) {
-        this->pp_depth -= 1;
+            int lines = this->pp_body_lines.top();
-        this->pp_body_lines.pop();
+            this->pp_depth -= 1;
-        this->pp_body_lines.top() += lines;
+            this->pp_body_lines.pop();
+            this->pp_body_lines.top() += lines;
+        }
+        else {
+            this->pp_body_lines.top() = 0;
+        }
     }
 
     void start_new_line() {

test/logfile_json.json

@@ -1,2 +1,13 @@
+{"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"}
+{"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"}

test/logfile_pretty.0

@@ -20,3 +20,4 @@ Apr  7 07:31:56 Tim-Stacks-iMac.local VirtualBox[36403]: WARNING: The Gestalt se
 	Call location:
 Apr  7 07:31:56 Tim-Stacks-iMac.local VirtualBox[36403]: 0   CarbonCore                          0x00007fff8a9b3d9b ___Gestalt_SystemVersion_block_invoke + 113
 Apr  7 07:31:56 Tim-Stacks-iMac.local VirtualBox[36403]: 1   libdispatch.dylib                   0x00007fff8bc84c13 _dispatch_client_callout + 8
+Apr  7 07:32:56 Tim-Stacks-iMac.local logger[234]: Bad data { abc, 123, 456 )}]

test/test_cmds.sh

@@ -437,6 +437,12 @@ Apr  7 07:31:56 Tim-Stacks-iMac.local VirtualBox[36403]: WARNING: The Gestalt se
 	Call location:
 Apr  7 07:31:56 Tim-Stacks-iMac.local VirtualBox[36403]: 0   CarbonCore                          0x00007fff8a9b3d9b ___Gestalt_SystemVersion_block_invoke + 113
 Apr  7 07:31:56 Tim-Stacks-iMac.local VirtualBox[36403]: 1   libdispatch.dylib                   0x00007fff8bc84c13 _dispatch_client_callout + 8
+Apr  7 07:32:56 Tim-Stacks-iMac.local logger[234]: Bad data {
+    abc,
+    123,
+    456
+)
+}]
 EOF
 
 

test/test_json_format.sh

@@ -8,15 +8,50 @@ run_test ${lnav_test} -n \
     ${test_dir}/logfile_json.json
 
 check_output "json log format is not working" <<EOF
+2013-09-06T20:00:48.124 TRACE trace test
 2013-09-06T20:00:49.124 INFO Starting up service
 2013-09-06T22:00:49.124 INFO Shutting down service
   user: steve@example.com
+2013-09-06T22:00:59.124 DEBUG5 Details...
+2013-09-06T22:00:59.124 DEBUG4 Details...
+2013-09-06T22:00:59.124 DEBUG3 Details...
+2013-09-06T22:00:59.124 DEBUG2 Details...
+2013-09-06T22:00:59.124 DEBUG Details...
+2013-09-06T22:01:49.124 STATS 1 beat per second
+2013-09-06T22:01:49.124 WARNING not looking good
+2013-09-06T22:01:49.124 ERROR looking bad
+2013-09-06T22:01:49.124 CRITICAL sooo bad
+2013-09-06T22:01:49.124 FATAL shoot
+EOF
+
+
+run_test ${lnav_test} -n -d /tmp/lnav.err \
+    -I ${test_dir} \
+    -c ';select * from test_log' \
+    -c ':write-csv-to -' \
+    ${test_dir}/logfile_json.json
+
+check_output "log levels not working" <<EOF
+log_line,log_part,log_time,log_idle_msecs,log_level,log_mark,user
+0,p.0,2013-09-06 20:00:48.124,0,trace,0,<NULL>
+1,p.0,2013-09-06 20:00:49.124,1000,info,0,<NULL>
+2,p.0,2013-09-06 22:00:49.124,7200000,info,0,steve@example.com
+4,p.0,2013-09-06 22:00:59.124,10000,debug5,0,<NULL>
+5,p.0,2013-09-06 22:00:59.124,0,debug4,0,<NULL>
+6,p.0,2013-09-06 22:00:59.124,0,debug3,0,<NULL>
+7,p.0,2013-09-06 22:00:59.124,0,debug2,0,<NULL>
+8,p.0,2013-09-06 22:00:59.124,0,debug,0,<NULL>
+9,p.0,2013-09-06 22:01:49.124,50000,stats,0,<NULL>
+10,p.0,2013-09-06 22:01:49.124,0,warning,0,<NULL>
+11,p.0,2013-09-06 22:01:49.124,0,error,0,<NULL>
+12,p.0,2013-09-06 22:01:49.124,0,critical,0,<NULL>
+13,p.0,2013-09-06 22:01:49.124,0,fatal,0,<NULL>
 EOF
 
 
 run_test ${lnav_test} -n \
     -I ${test_dir} \
-    -c ":goto 1" \
+    -c ":goto 2" \
     -c ":pipe-line-to sed -e 's/2013//g'" \
     -c ":switch-to-view text" \
     ${test_dir}/logfile_json.json

test/test_logfile.sh

@@ -118,41 +118,41 @@ EOF
 run_test ./drive_logfile -v -f syslog_log ${srcdir}/logfile_syslog.0
 
 check_output "Syslog level interpreted incorrectly?" <<EOF
-0x05
+0x0a
-0x03
+0x07
-0x05
+0x0a
-0x03
+0x07
 EOF
 
 run_test ./drive_logfile -v -f tcsh_history ${srcdir}/logfile_tcsh_history.0
 
 check_output "TCSH level interpreted incorrectly?" <<EOF
-0x03
+0x07
-0x83
+0x87
-0x03
+0x07
-0x83
+0x87
 EOF
 
 run_test ./drive_logfile -v -f access_log ${srcdir}/logfile_access_log.0
 
 check_output "access_log level interpreted incorrectly?" <<EOF
-0x03
+0x07
-0x05
+0x0a
-0x03
+0x07
 EOF
 
 run_test ./drive_logfile -v -f strace_log ${srcdir}/logfile_strace_log.0
 
 check_output "strace_log level interpreted incorrectly?" <<EOF
-0x03
+0x07
-0x03
+0x07
-0x03
+0x07
-0x05
+0x0a
-0x03
+0x07
-0x05
+0x0a
-0x03
+0x07
-0x03
+0x07
-0x03
+0x07
 EOF
 
 run_test ./drive_logfile -t -f generic_log ${srcdir}/logfile_generic.0
@@ -165,8 +165,8 @@ EOF
 run_test ./drive_logfile -v -f generic_log ${srcdir}/logfile_generic.0
 
 check_output "generic_log level interpreted incorrectly?" <<EOF
-0x02
+0x06
-0x04
+0x09
 EOF
 
 touch -t 200711030923 ${srcdir}/logfile_glog.0
@@ -185,13 +185,13 @@ EOF
 run_test ./drive_logfile -v -f glog_log ${srcdir}/logfile_glog.0
 
 check_output "glog_log level interpreted incorrectly?" <<EOF
-0x05
+0x0a
-0x03
+0x07
-0x03
+0x07
-0x04
+0x09
-0x03
+0x07
-0x03
+0x07
-0x05
+0x0a
 EOF
 
 cp ${srcdir}/logfile_syslog.0 truncfile.0