hack/log-explainer: Expand SVG waterfall to explain more of the log

Making it easier to dig into the individual sync cycles, find
goroutines that have hung, etc.

Author: wking

hack/log-explainer.py

@@ -0,0 +1,307 @@
+#!/usr/bin/python3
+#
+#   $ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-origin-installer-e2e-aws-upgrade/1301652659597479936/artifacts/e2e-aws-upgrade/pods/openshift-cluster-version_cluster-version-operator-6b6bc46c59-dk8bm_cluster-version-operator.log | log-explainer.py
+#   $ xdg-open index.html
+
+import datetime
+import logging
+import re
+import sys
+
+
+# klog format parser
+# https://github.com/kubernetes/klog/blob/v2.3.0/klog.go#L571-L585
+log_regexp = re.compile('''^
+    .*  # must-gather leading timestamp
+    (?P<level>[IWEF])  # I(nfo), W(arning), E(rror), F(atal)
+    (?P<month>[0-1][0-9])(?P<day>[0-3][0-9])[ ](?P<time>[0-9][0-9]:[0-9][0-9]:[0-9][0-9][.][0-9]+)  # timestamp
+    [ ]+
+    (?P<thread>[0-9]+)  # thread ID as returned by GetTID()
+    [ ]
+    (?P<file>[^:]*):(?P<line>[0-9]+)]
+    [ ]
+    (?P<message>.*)$
+''', re.VERBOSE)
+
+
+levels = {
+    'I': 'Info',
+    'W': 'Warning',
+    'E': 'Error',
+    'F': 'Fatal',
+}
+
+
+start_of_sync_cycle_regexp = re.compile('^Running sync (?P<version>[^ ]+) \(force=(?P<force>[^)]+)\) on generation (?P<generation>[0-9]+) in state (?P<state>[^ ]+) at attempt (?P<attempt>[0-9]+)$')
+end_of_sync_cycle_prefix = 'Result of work: '
+manifest_regexp = re.compile('^(?P<action>Running sync|Done syncing|error running apply) for (?P<type>[^ ]+) "(?P<name>[^"]+)" \((?P<index>[0-9]+) of (?P<total>[0-9]+)\)(?P<suffix>.*)$')
+
+
+def read_klog(stream):
+    lines = []
+    line = None
+    year = datetime.date.today().year  # assume the log is from this calendar year
+    for line_string in sys.stdin.readlines():
+        match = log_regexp.match(line_string)
+        if not match:
+            if line and line_string.strip():
+                line['message'] += '\n' + line_string.strip()
+            continue
+        groups = match.groupdict()
+        groups['year'] = year
+        timestamp = datetime.datetime.strptime('{year} {month} {day} {time}'.format(**groups), '%Y %m %d %H:%M:%S.%f')
+        line = {
+            'level': levels[groups['level']],
+            'time': timestamp,
+            'thread': int(groups['thread']),
+            'file': groups['file'],
+            'line': int(groups['line']),
+            'message': groups['message'],
+        }
+        lines.append(line)
+    return lines
+
+
+def parse_lines(lines):
+    metadata = {
+        'version': lines[0]['message'],
+        'start_time': lines[0]['time'],
+        'stop_time': lines[-1]['time'],
+        'threads': len({line['thread'] for line in lines}),
+
+        # goroutines
+        'available updates sync': [line for line in lines if line['file'] == 'availableupdates.go' or 'syncing available updates' in line['message']],
+        'cluster version sync': [line for line in lines if 'syncing cluster version' in line['message'] or 'Desired version from' in line['message']],
+        'metrics': [line for line in lines if line['file'] == 'metrics.go'],
+        'sync worker': [line for line in lines if line['file'] in ['sync_worker.go', 'task.go', 'task_graph.go', 'warnings.go']],
+        'upgradeable': [line for line in lines if line['file'] == 'upgradeable.go' or 'syncing upgradeable' in line['message']],
+    }
+
+    metadata['leader_elections'] = [line for line in lines if line['file'] == 'leaderelection.go']
+    acquired_leader_lease = [line for line in metadata['leader_elections'] if 'successfully acquired lease' in line['message']]
+    if acquired_leader_lease:
+        metadata['time_to_leader_lease'] = acquired_leader_lease[0]['time'] - metadata['start_time']
+
+    sync = None
+    metadata['syncs'] = []
+    for line in metadata['sync worker']:
+        match = start_of_sync_cycle_regexp.match(line['message'])
+        if match:
+            sync = match.groupdict()
+            sync['start_time'] = line['time']
+            sync['lines'] = []
+            sync['manifests'] = {}
+            metadata['syncs'].append(sync)
+        if sync:
+            sync['lines'].append(line)
+        else:
+            logging.warning('sync worker line outside of sync: {}'.format(line))
+        if line['message'].startswith(end_of_sync_cycle_prefix):
+            sync['results'] = {
+                'result': line['message'][len(end_of_sync_cycle_prefix):],
+            }
+            sync['results'].update(line)
+        match = manifest_regexp.match(line['message'])
+        if match:
+            groups = match.groupdict()
+            for key in ['index', 'total']:
+                groups[key] = int(groups[key])
+            groups.update(line)
+            manifest_key = (groups['type'], groups['name'])
+            if manifest_key not in sync['manifests']:
+                sync['manifests'][manifest_key] = []
+            sync['manifests'][manifest_key].append(groups)
+    for sync in metadata['syncs']:
+        sync['failed_manifests'] = {k: m for (k, m) in sync['manifests'].items() if m[-1]['action'] == 'error running apply'}
+
+    metadata['unclassified'] = [
+        line for line in lines
+        if 'ClusterVersionOperator' not in line['message'] and
+        line not in metadata['available updates sync'] and
+        line not in metadata['cluster version sync'] and
+        line not in metadata['metrics'] and
+        line not in metadata['sync worker'] and
+        line not in metadata['upgradeable'] and
+        line not in metadata['leader_elections']
+    ]
+    return metadata
+
+
+def write_sync_svg(path, metadata):
+    time_ranges = {}
+    for sync in metadata['syncs']:
+        for key, manifest in sync['manifests'].items():
+            start = (manifest[0]['time'] - metadata['start_time']).total_seconds()
+            if 'Done syncing' in manifest[-1]['action']:
+                stop = (manifest[-1]['time'] - metadata['start_time']).total_seconds()
+            else:
+                stop = None
+            if key in time_ranges:
+                previous = time_ranges[key]
+                if previous[1]:
+                    stop = previous[1]
+                time_ranges[key] = (previous[0], stop, previous[2], previous[3], manifest)
+            else:
+                time_ranges[key] = (start, stop, manifest[0]['type'], manifest[0]['name'], manifest)
+
+    for _, stop, objType, name, manifest in sorted(time_ranges.values()):
+        if not stop:
+            logging.warning('not finished: {} {}{}'.format(objType, name, manifest[-1]['suffix']))
+
+    rectangles = []
+    y = 0
+    step = 4
+    last_stop = 0
+    max_stop = (metadata['stop_time'] - metadata['start_time']).total_seconds()
+    for start, stop, objType, name, manifest in sorted(time_ranges.values()):
+        if stop is None:
+            stop = max_stop
+            fill = 'red'
+        else:
+            fill = 'blue'
+        rectangles.append('<rect x="{}" y="{}" width="{}" height="{}" fill="{}"><title>{} {} {}/{} ({})</title></rect>'.format(start, y, stop - start, step, fill, objType, name, manifest[0]['index'], manifest[0]['total'], stop - start))
+        y += step
+        if stop > last_stop:
+            last_stop = stop
+
+    with open(path, 'w') as f:
+        f.write('<svg viewBox="0 0 {} {}" xmlns="http://www.w3.org/2000/svg">\n'.format(last_stop, y))
+        duration = datetime.timedelta(seconds=last_stop)
+        time_scale = 5
+        for i in range(1 + int(last_stop // (time_scale*60))):
+            f.write('  <line x1="{x}"  x2="{x}" y1="0%" y2="100%" stroke="gray" style="stroke-opacity: 0.5;"><title>{minutes} minutes</title></line>\n'.format(
+                x=i * time_scale * 60,
+                minutes=i * time_scale))
+        for rectangle in rectangles:
+            f.write('  {}\n'.format(rectangle))
+        f.write('  <text x="50%" y="20" text-anchor="middle">CVO manifests, duration {}</text>\n'.format(duration))
+        f.write('</svg>\n')
+
+
+def write_log_lines(stream, lines):
+    # FIXME: write to separate files?
+    if lines:
+        stream.write('<pre>\n{}\n</pre>\n'.format(
+            '\n'.join(
+                '{} {} {}'.format(line['time'], line['file'], line['message']) for line in lines
+            )
+        ))
+    else:
+        stream.write('    <p>No log lines.</p>\n')
+
+
+def write_index(path, metadata, sync_svg):
+    with open(path, 'w') as f:
+        f.write('''<!doctype html>
+<html lang="en">
+<head>
+  <title>Cluster-version operator log</title>
+  <style type="text/css">
+    .warning {
+      font-weight: bold;
+      color: red;
+    }
+    pre {
+        font-size: 80%;
+    }
+  </style>
+</head>
+<body>
+  <h1>Cluster-version operator log</h1>
+''')
+        f.write('  <dl>\n')
+        for key in [
+                'version',
+                'start_time',
+                'stop_time',
+                'threads',
+                ]:
+            f.write('    <dt>{}</dt>\n    <dd>{}</dd>\n'.format(key, metadata.get(key, '-')))
+        f.write('  </dl>\n')
+
+        f.write('  <h2>Leader election</h2>\n')
+        if metadata.get('time_to_leader_lease'):
+            warning = ''
+            if metadata['time_to_leader_lease'].total_seconds() > 30:
+                warning = ' class="warning"'
+            f.write('  <p{}>Leader lease acquired in {}.</p>'.format(warning, metadata['time_to_leader_lease']))
+        else:
+            f.write('  <p class="warning">Leader lease never acquired.</p>')
+        write_log_lines(stream=f, lines=metadata.get('leader_elections'))
+
+        f.write('  <h2>Peripheral goroutines</h2>\n')
+        for key in [
+                'available updates sync',
+                'cluster version sync',
+                'metrics',
+                'upgradeable',
+                ]:
+            f.write('   <h3 id="{0}">{0}</h3>\n'.format(key))
+            gorountine_lines = metadata.get(key)
+            if gorountine_lines:
+                time_to_start = gorountine_lines[0]['time'] - metadata['start_time']
+                time_since_final_log = metadata['stop_time'] - gorountine_lines[-1]['time']
+                warning = ''
+                if (
+                        time_to_start.total_seconds() > 2*60 or
+                        (time_since_final_log.total_seconds() > 5*60 and key != 'metrics')  # metrics server does not log periodically
+                        ):
+                    warning = ' class="warning"'
+                f.write('  <p{}>Goroutine beings logging {} after the initial container log entry and is last seen {} before the final container log entry.</p>\n'.format(
+                    warning, time_to_start, time_since_final_log,
+                ))
+
+        if metadata.get('unclassified'):
+            f.write('  <h2>Unclassified log lines</h2>\n')
+            write_log_lines(stream=f, lines=metadata['unclassified'])
+
+        f.write('  <h2 id="sync-cycles">Sync cycles</h2>\n')
+        version = None
+        mode = None
+        for sync in metadata['syncs']:
+            if sync['version'] != version:
+                f.write('  <h3>{}</h3>\n'.format(sync['version']))
+            version = sync['version']
+            if (sync['state'], sync['force']) != mode:
+                f.write('  <h4>{} (force={})</h4>\n'.format(sync['state'], sync['force']))
+            mode = (sync['state'], sync['force'])
+            end = 'running'
+            if 'results' in sync:
+                end = sync['results']['time']
+            result = 'running'
+            if 'results' in sync:
+                if sync['results']['result'] == '[]':
+                    result = 'success'
+                else:
+                    result = 'failure'
+            f.write('  <h5>Attempt {} {}: {} - {}</h5>\n'.format(sync['attempt'], result, sync['start_time'], end))
+            f.write('  <dl>\n')
+            for (key, value) in [
+                    ('lines', len(sync['lines'])),
+                    ('result', sync.get('results', {}).get('result', 'running')),
+                    ('manifests attempted', len(sync['manifests'])),
+                    ]:
+                f.write('    <dt>{}</dt>\n    <dd>{}</dd>\n'.format(key, value))
+            f.write('  </dl>\n')
+            if sync['failed_manifests']:
+                f.write('  <p>Failed manifests:</p>\n')
+                f.write('  <ul>\n')
+                for lines in sorted(sync['failed_manifests'].values(), key=lambda lines: lines[-1]['index']):
+                    f.write('    <li>{time} {message}</li>\n'.format(**lines[-1]))
+                f.write('  </ul>\n')
+
+        if metadata['sync worker']:
+            time_since_final_log = metadata['stop_time'] - metadata['sync worker'][-1]['time']
+            if time_since_final_log.total_seconds() > 5*60:
+                f.write('  <p class="warning">Goroutine is last seen {} before the final container log entry.</p>\n'.format(time_since_final_log))
+
+        f.write('  <div style="text-align:center">\n    <object data="{}" type="image/svg+xml" width="100%" />\n  </div>\n'.format(sync_svg))
+
+        f.write('</body>\n</html>\n')
+
+
+if __name__ == '__main__':
+    lines = read_klog(stream=sys.stdin)
+    metadata = parse_lines(lines=lines)
+    write_sync_svg(path='sync.svg', metadata=metadata)
+    write_index(path='index.html', metadata=metadata, sync_svg='sync.svg')