From add528532e3c1a5604d512d8411d2b454d7c8da1 Mon Sep 17 00:00:00 2001
From: Kevin O'Connor <kevin@koconnor.net>
Date: Tue, 12 Dec 2017 15:51:50 -0500
Subject: [PATCH] logextract: Rename extractconfig.py to logextract.py and add
 shutdown parsing

Add initial support for extracting out shutdown information from a
klippy.log file.  The shutdown dump will be reordered into the
sequence that they occurred, and timestamps/sequence numbers in the
mcu message dump will be expanded.

Signed-off-by: Kevin O'Connor <kevin@koconnor.net>
---
 scripts/extractconfig.py |  56 ---------
 scripts/logextract.py    | 259 +++++++++++++++++++++++++++++++++++++++
 2 files changed, 259 insertions(+), 56 deletions(-)
 delete mode 100755 scripts/extractconfig.py
 create mode 100755 scripts/logextract.py

diff --git a/scripts/extractconfig.py b/scripts/extractconfig.py
deleted file mode 100755
index b50afc51..00000000
--- a/scripts/extractconfig.py
+++ /dev/null
@@ -1,56 +0,0 @@
-#!/usr/bin/env python2
-# Script to extract a config file from a log
-#
-# Copyright (C) 2017  Kevin O'Connor <kevin@koconnor.net>
-#
-# This file may be distributed under the terms of the GNU GPLv3 license.
-import sys
-
-def format_comment(line_num, line):
-    return "# %6d: %s" % (line_num, line)
-
-def main():
-    logname = sys.argv[1]
-    f = open(logname, 'rb')
-    last_git = last_start = ''
-    config_count = config_line_num = 0
-    configs = {}
-    config_lines = []
-    info = None
-    # Parse log file
-    for line_num, line in enumerate(f):
-        line = line.strip()
-        line_num += 1
-        if config_line_num:
-            if line == '=======================':
-                lines = tuple(config_lines)
-                info = configs.get(lines)
-                if info is None:
-                    config_count += 1
-                    configs[lines] = info = (config_count, [])
-                info[1].append(format_comment(config_line_num, "config file"))
-                if last_git:
-                    info[1].append(last_git)
-                if last_start:
-                    info[1].append(last_start)
-                config_line_num = 0
-                config_lines = []
-            else:
-                config_lines.append(line)
-        elif line.startswith('Git version'):
-            last_git = format_comment(line_num, line)
-        elif line.startswith('Start printer at'):
-            last_start = format_comment(line_num, line)
-        elif line == '===== Config file =====':
-            config_line_num = line_num
-        elif info is not None and (
-                ' shutdown: ' in line or line.startswith('Dumping ')):
-            info[1].append(format_comment(line_num, line))
-    # Write found config files
-    for lines, (count, comments) in configs.items():
-        f = open("%s.config%04d.cfg" % (logname, count), 'wb')
-        f.write('\n'.join(tuple(comments) + lines))
-        f.close()
-
-if __name__ == '__main__':
-    main()
diff --git a/scripts/logextract.py b/scripts/logextract.py
new file mode 100755
index 00000000..0fb9dcca
--- /dev/null
+++ b/scripts/logextract.py
@@ -0,0 +1,259 @@
+#!/usr/bin/env python2
+# Script to extract a config file from a log
+#
+# Copyright (C) 2017  Kevin O'Connor <kevin@koconnor.net>
+#
+# This file may be distributed under the terms of the GNU GPLv3 license.
+import sys, re, collections
+
+def format_comment(line_num, line):
+    return "# %6d: %s" % (line_num, line)
+
+
+######################################################################
+# Config file extraction
+######################################################################
+
+class GatherConfig:
+    def __init__(self, configs, line_num, recent_lines, logname):
+        self.configs = configs
+        self.line_num = line_num
+        self.config_num = len(configs) + 1
+        self.filename = "%s.config%04d.cfg" % (logname, self.config_num)
+        self.config_lines = []
+        self.comments = []
+    def add_line(self, line_num, line):
+        if line != '=======================':
+            self.config_lines.append(line)
+            return True
+        self.finalize()
+        return False
+    def finalize(self):
+        lines = tuple(self.config_lines)
+        ch = self.configs.get(lines)
+        if ch is None:
+            self.configs[lines] = ch = self
+        else:
+            ch.comments.extend(self.comments)
+        ch.comments.append(format_comment(self.line_num, "config file"))
+    def add_comment(self, comment):
+        if comment is not None:
+            self.comments.append(comment)
+    def write_file(self):
+        f = open(self.filename, 'wb')
+        f.write('\n'.join(self.comments + self.config_lines))
+        f.close()
+
+
+######################################################################
+# Shutdown extraction
+######################################################################
+
+stats_seq_s = r" send_seq=(?P<sseq>[0-9]+) receive_seq=(?P<rseq>[0-9]+) "
+count_s = r"(?P<count>[0-9]+)"
+time_s = r"(?P<time>[0-9]+[.][0-9]+)"
+esttime_s = r"(?P<esttime>[0-9]+[.][0-9]+)"
+shortseq_s = r"(?P<shortseq>[0-9a-f])"
+stats_r = re.compile(r"^Stats " + time_s + ": .*" + stats_seq_s)
+serial_dump_r = re.compile(r"^Dumping serial stats: .*" + stats_seq_s)
+send_dump_r = re.compile(r"^Dumping send queue " + count_s + " messages$")
+sent_r = re.compile(r"^Sent " + count_s + " " + esttime_s + " " + time_s
+                    + " [0-9]+: seq: 1" + shortseq_s + ",")
+receive_dump_r = re.compile(r"^Dumping receive queue " + count_s + " messages$")
+receive_r = re.compile(r"^Receive: " + count_s + " " + time_s + " " + esttime_s
+                    + " [0-9]+: seq: 1" + shortseq_s + ",")
+gcode_r = re.compile(r"^Read " + time_s + ": ['\"]")
+clock_r = re.compile(r"^clocksync state: .* clock_est=\((?P<st>[^ ]+)"
+                     + r" (?P<sc>[0-9]+) (?P<f>[^ ]+)\)")
+repl_seq_r = re.compile(r": seq: 1" + shortseq_s)
+repl_clock_r = re.compile(r"clock=(?P<clock>[0-9]+) ")
+
+def add_high_bits(val, ref, mask):
+    half = (mask + 1) // 2
+    return ref + ((val - (ref & mask) + half) & mask) - half
+
+class GatherShutdown:
+    def __init__(self, configs, line_num, recent_lines, logname):
+        self.shutdown_line_num = line_num
+        self.filename = "%s.shutdown%05d" % (logname, line_num)
+        configs_by_id = {c.config_num: c for c in configs.values()}
+        self.config = configs_by_id[max(configs_by_id.keys())]
+        self.comments = ["# config %s" % (self.config.filename,)]
+        self.config.add_comment(format_comment(line_num, recent_lines[-1][1]))
+        self.stats_stream = []
+        self.gcode_stream = []
+        self.sent_stream = []
+        self.receive_stream = []
+        self.sent_time_to_seq = {}
+        self.sent_seq_to_time = {}
+        self.receive_seq_to_time = {}
+        self.clock_est = 0., 0., 1.
+        self.shutdown_seq = None
+        self.first_stat_time = self.last_stat_time = None
+        self.send_count = self.receive_count = 0
+        for line_num, line in recent_lines:
+            self.parse_line(line_num, line)
+        self.first_stat_time = self.last_stat_time
+    def add_comment(self, comment):
+        if comment is not None:
+            self.comments.append(comment)
+    def trans_clock(self, clock, ts):
+        sample_time, sample_clock, freq = self.clock_est
+        exp_clock = int(sample_clock + (ts - sample_time) * freq)
+        ext_clock = add_high_bits(clock, exp_clock, 0xffffffff)
+        return sample_time + (ext_clock - sample_clock) / freq
+    def annotate(self, line, seq, ts):
+        line = repl_seq_r.sub(r"\g<0>(%d)" % (seq,), line)
+        def clock_update(m):
+            return m.group(0)[:-1] + "(%.6f) " % (
+                self.trans_clock(int(m.group('clock')), ts),)
+        line = repl_clock_r.sub(clock_update, line)
+        return line
+    def add_line(self, line_num, line):
+        self.parse_line(line_num, line)
+        if (self.first_stat_time is not None
+            and self.last_stat_time > self.first_stat_time + 5.):
+            self.finalize()
+            return False
+        if (line.startswith('Git version') or line.startswith('Start printer at')
+            or line == '===== Config file ====='):
+            self.finalize()
+            return False
+        return True
+    def parse_line(self, line_num, line):
+        m = sent_r.match(line)
+        if m is not None:
+            shortseq = int(m.group('shortseq'), 16)
+            seq = self.shutdown_seq + int(m.group('count')) - self.send_count
+            seq = add_high_bits(shortseq, seq, 0xf)
+            ts = float(m.group('time'))
+            esttime = float(m.group('esttime'))
+            self.sent_time_to_seq[(esttime, seq & 0xf)] = seq
+            self.sent_seq_to_time[seq] = ts
+            line = self.annotate(line, seq, ts)
+            self.sent_stream.append((ts, line_num, line))
+            return
+        m = receive_r.match(line)
+        if m is not None:
+            shortseq = int(m.group('shortseq'), 16)
+            ts = float(m.group('time'))
+            esttime = float(m.group('esttime'))
+            seq = self.sent_time_to_seq.get((esttime, (shortseq - 1) & 0xf))
+            if seq is not None:
+                self.receive_seq_to_time[seq + 1] = ts
+            line = self.annotate(line, seq, ts)
+            self.receive_stream.append((ts, line_num, line))
+            return
+        m = gcode_r.match(line)
+        if m is not None:
+            ts = float(m.group('time'))
+            self.gcode_stream.append((ts, line_num, line))
+            return
+        m = stats_r.match(line)
+        if m is not None:
+            ts = float(m.group('time'))
+            sseq = int(m.group('sseq'))
+            rseq = int(m.group('rseq'))
+            self.last_stat_time = ts
+            if self.first_stat_time is None:
+                self.first_stat_time = ts
+            self.stats_stream.append((ts, sseq, rseq, line_num, line))
+            return
+        m = clock_r.match(line)
+        if m is not None:
+            st = float(m.group('st'))
+            sc = int(m.group('sc'))
+            f = float(m.group('f'))
+            self.clock_est = (st, sc, f)
+        m = serial_dump_r.match(line)
+        if m is not None:
+            self.shutdown_seq = int(m.group('rseq'))
+        m = send_dump_r.match(line)
+        if m is not None:
+            self.send_count = int(m.group('count'))
+        m = receive_dump_r.match(line)
+        if m is not None:
+            self.receive_count = int(m.group('count'))
+        self.stats_stream.append((None, None, None, line_num, line))
+    def finalize(self):
+        # Ignore old stats
+        stream_ts = [i[0] for i in self.sent_stream + self.receive_stream]
+        if not stream_ts:
+            return
+        min_stream_ts = min(stream_ts)
+        max_stream_ts = max(stream_ts)
+        for i, info in enumerate(self.stats_stream):
+            if info[0] is not None and info[0] >= min_stream_ts - 5.:
+                del self.stats_stream[:i]
+                break
+        # Improve accuracy of stats timestamps
+        last_ts = self.stats_stream[0][0]
+        out = []
+        for i in range(len(self.stats_stream)):
+            ts, sseq, rseq, line_num, line = self.stats_stream[i]
+            if ts is not None:
+                min_ts = max(self.sent_seq_to_time.get(sseq-1, 0),
+                             self.receive_seq_to_time.get(rseq, 0))
+                max_ts = min(self.sent_seq_to_time.get(sseq, 999999999999),
+                             self.receive_seq_to_time.get(rseq+1, 999999999999))
+                last_ts = min(max(ts, min_ts + 0.00000001),
+                              max_ts - 0.00000001)
+            elif line_num >= self.shutdown_line_num and last_ts <= max_stream_ts:
+                last_ts = max_stream_ts + 0.00000001
+            out.append((last_ts, line_num, line))
+        # Make sure no timestamp goes backwards
+        for s in [self.sent_stream, self.receive_stream, self.gcode_stream]:
+            for i in range(1, len(s)):
+                if s[i-1][0] > s[i][0]:
+                    s[i] = (s[i-1][0], s[i][1], s[i][2])
+        # Produce output sorted by timestamp
+        out = out + self.sent_stream + self.receive_stream + self.gcode_stream
+        out.sort()
+        out = [i[2] for i in out]
+        f = open(self.filename, 'wb')
+        f.write('\n'.join(self.comments + out))
+        f.close()
+
+
+######################################################################
+# Startup
+######################################################################
+
+def main():
+    logname = sys.argv[1]
+    last_git = last_start = None
+    configs = {}
+    handler = None
+    recent_lines = collections.deque([], 200)
+    # Parse log file
+    f = open(logname, 'rb')
+    for line_num, line in enumerate(f):
+        line = line.rstrip()
+        line_num += 1
+        recent_lines.append((line_num, line))
+        if handler is not None:
+            ret = handler.add_line(line_num, line)
+            if ret:
+                continue
+            recent_lines.clear()
+            handler = None
+        if line.startswith('Git version'):
+            last_git = format_comment(line_num, line)
+        elif line.startswith('Start printer at'):
+            last_start = format_comment(line_num, line)
+        elif line == '===== Config file =====':
+            handler = GatherConfig(configs, line_num, recent_lines, logname)
+            handler.add_comment(last_git)
+            handler.add_comment(last_start)
+        elif 'shutdown: ' in line or line.startswith('Dumping '):
+            handler = GatherShutdown(configs, line_num, recent_lines, logname)
+            handler.add_comment(last_git)
+            handler.add_comment(last_start)
+    if handler is not None:
+        handler.finalize()
+    # Write found config files
+    for cfg in configs.values():
+        cfg.write_file()
+
+if __name__ == '__main__':
+    main()