[sheepdog] [PATCH v3 4/4] script: json_log_viewer.py for collecting and viewing multiple log files of sheeps

[Hitoshi Mitake]

This patch adds a new script: json_log_viewer.py for collecting and
viewing multiple log files of sheeps.

This script is useful for reading log files produced during running
test scripts. Because test scripts execute every sheep process on one
machine, sorting their log entries with timestamp is meaningful.

Simple description of usage and screenshot is here:
http://github.com/mitake/sheepdog/wiki/json_log_viewer.py

Signed-off-by: Hitoshi Mitake <mitake.hitoshi at lab.ntt.co.jp>
---
 script/json_log_viewer.py |  224 +++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 224 insertions(+), 0 deletions(-)
 create mode 100755 script/json_log_viewer.py

diff --git a/script/json_log_viewer.py b/script/json_log_viewer.py
new file mode 100755
index 0000000..d6d1ff8
--- /dev/null
+++ b/script/json_log_viewer.py
@@ -0,0 +1,224 @@
+#! /usr/bin/env python
+
+import sys, os, errno
+import json, curses
+import atexit
+
+dying_msg = ''
+
+w = None
+curses_colors = [
+    curses.COLOR_RED,
+    curses.COLOR_GREEN,
+    curses.COLOR_YELLOW,
+    curses.COLOR_BLUE,
+    curses.COLOR_MAGENTA,
+    curses.COLOR_CYAN,
+    ]
+nr_curses_colors = len(curses_colors)
+
+def init_curses():
+    global w
+
+    w = curses.initscr()
+    curses.nonl()
+    curses.cbreak()
+    curses.noecho()
+
+    curses.start_color()
+    for i in range(1, nr_curses_colors + 1):
+        curses.init_pair(i, curses_colors[i - 1], curses.COLOR_BLACK)
+
+def read_log_files(file_names):
+    nodes = []
+
+    for file_name in file_names:
+        f = open(file_name)
+
+        # read header of this log file
+        hdr_line = f.readline()
+        hdr_json = json.loads(hdr_line)
+        assert hdr_json['type'] == 0     # 0 means header
+        hdr = hdr_json['header']
+
+        # read log records
+        logs = []
+        for line in f.readlines():
+            log = json.loads(line)
+            if log['type'] != 1:
+                continue
+
+            body = log['body']
+
+            sec = body['second']
+            usec = body['usecond']
+
+            del body['second']
+            del body['usecond']
+
+            logs.append({ 'timestamp': (sec, usec), 'body': body})
+
+        nodes.append({'header': hdr, 'logs': logs})
+
+    return nodes
+
+def assign_color(nodes):
+    sheeps = []
+    for node in nodes:
+        if node['header']['program'] == 'sheep':
+            sheeps.append(node)
+    nr_sheeps = len(sheeps)
+
+    if nr_curses_colors < nr_sheeps:
+        # we don't have enough colors to assign...
+        return
+
+    for i in range(0, nr_sheeps):
+        sheeps[i]['header']['color'] = i + 1
+
+begin_sec, begin_usec = -1, -1
+
+def unify_nodes(nodes):
+    def is_not_empty(nodes):
+        for node in nodes:
+            logs = node['logs']
+            if len(logs) != 0:
+                return True
+        return False
+
+    def get_node_of_next_log(nodes):
+        ret = None
+
+        for node in nodes:
+            if len(node['logs']) == 0:
+                continue
+
+            if ret == None:
+                ret = node
+                min_sec, min_usec = ret['logs'][0]['timestamp']
+
+                global begin_sec, begin_usec
+                if begin_sec == -1:
+                    begin_sec = min_sec
+                    assert begin_usec == -1
+                    begin_usec = min_usec
+                continue
+
+            sec, usec = node['logs'][0]['timestamp']
+            if sec == min_sec:
+                if usec == min_usec:
+                    # we have two records with same timestamp
+                    # prioritize first found one
+                    continue
+                if usec < min_usec:
+                    ret = node
+            elif sec < min_sec:
+                ret = node
+
+        return ret
+
+    unified = []
+    while is_not_empty(nodes):
+        node = get_node_of_next_log(nodes)
+        unified.append((node['header'], node['logs'][0]))
+        del node['logs'][0]
+
+    return unified
+
+current_y = 0
+max_y, max_x = 0, 0
+unified_len = 0
+unified = []
+
+def format_line(record):
+    header, log = record
+
+    sec, usec = log['timestamp']
+    udelta = usec - begin_usec
+    if udelta < 0:
+        udelta += 1000000
+        sec -= 1
+    udeltas = '%06d' % udelta
+    t = '%d.%s' % (sec - begin_sec, udeltas)
+    ret = '%s+%s: ' % (' ' * (10 - len(t[:10])), t[:10])
+    body = log['body']
+    if header['program'] == 'sheep':
+        hdr = 'sheep %d,%s(%d) ' % \
+            (header['port'], body['func'], body['line'])
+        ret += hdr[:40] + ' ' * (40 - len(hdr[:40]) + 1)
+        ret += body['msg']
+
+        return ret[:max_x - 1]
+
+    global dying_msg
+    dying_msg = 'log from unknown program is found'
+    sys.exit(1)
+
+def update_terminal():
+    w.clear()
+
+    for i in range(0, max_y):
+        w.move(i, 0)
+        if not current_y + i < unified_len:
+            break
+        record = unified[current_y + i]
+        header, _ = record
+
+        if header.has_key('color'):
+            w.attrset(curses.color_pair(header['color']))
+
+        w.addstr(format_line(record))
+
+        if header.has_key('color'):
+            w.attroff(curses.color_pair(header['color']))
+
+    w.refresh()
+
+if __name__ == '__main__':
+    @atexit.register
+    def exit_handler():
+        curses.endwin()
+        if dying_msg != '':
+            print dying_msg + '\n'
+
+    init_curses()
+
+    nodes = read_log_files(sys.argv[1:])
+    assign_color(nodes)
+    unified = unify_nodes(nodes)
+    unified_len = len(unified)
+
+    tty_file = open('/dev/tty', 'rb')
+
+    max_y, max_x = w.getmaxyx()
+    update_terminal()
+    running = True
+
+    while running:
+        try:
+            key = tty_file.read(1)
+        except IOError, (enr, msg):
+            if enr == errno.EINTR:
+                continue
+
+            dying_msg = 'fatal error: %s' % \
+                (os.strerror(enr))
+            break
+
+        if key == 'q':
+            break
+        elif key == 'j':
+            if current_y + 1 < unified_len:
+                current_y += 1
+        elif key == 'k':
+            if current_y:
+                current_y -= 1
+        elif key == ' ':
+            if current_y + max_y < unified_len:
+                current_y += max_y
+        elif key == 'g':
+            current_y = 0
+        elif key == 'G':
+            current_y = unified_len - max_y
+
+        update_terminal()
-- 
1.7.2.5