From d1ad38f0ee41aac26d93ee7e329abcc0380c4c34 Mon Sep 17 00:00:00 2001 From: Tomas Krizek Date: Fri, 14 Aug 2020 18:16:46 +0200 Subject: [PATCH] scripts/bugreport-journals: pythonize the script --- scripts/bugreport-journals.py | 246 +++++++++++++++++++--------------- 1 file changed, 136 insertions(+), 110 deletions(-) diff --git a/scripts/bugreport-journals.py b/scripts/bugreport-journals.py index dcbc12900..d66ddfba4 100755 --- a/scripts/bugreport-journals.py +++ b/scripts/bugreport-journals.py @@ -1,12 +1,11 @@ #!/usr/bin/python3 """ -Collect sysmted-journald log entries around time of daemon exit and coredumps. +Collect systemd-journal log entries around time of daemon exit and coredumps. """ import datetime import json import logging -import os import pathlib import shutil import subprocess @@ -15,154 +14,181 @@ import sys TIMESPAN_BEFORE = 600 # s TIMESPAN_AFTER = TIMESPAN_BEFORE +CURSOR_DIR = pathlib.Path('/var/lib/knot-resolver') +CURSOR_PATH = CURSOR_DIR / 'coredump_watcher.cursor' -class Cursors: - cursordir = pathlib.Path('/var/lib/knot-resolver') - path = cursordir / pathlib.Path('coredump_watcher.cursor') +class Timestamp: + def __init__(self, usec): + self.usec = int(usec) - @staticmethod - def overwrite_previous(new_cursor): - logging.info('log cursor saved into %s, next run will skip old logs', - Cursors.path) - Cursors.cursordir.mkdir(parents=True, exist_ok=True) - with Cursors.path.open('w') as curfile: - curfile.write(new_cursor) + @property + def unix(self): + return self.usec // 10**6 - @staticmethod - def get_previous(): - try: - with Cursors.path.open('r') as curfile: - logging.info('log cursor read from %s, skipping old logs', - Cursors.path) - return curfile.read().strip() - except FileNotFoundError: - logging.info('log cursor file %s does not exist, parsing all logs', - Cursors.path) + def __str__(self): + return datetime.datetime.utcfromtimestamp(self.unix).strftime('%Y-%m-%d_%H:%M:%S') + + def __lt__(self, other): + return self.usec < other.usec + + def __eq__(self, other): + return self.usec == other.usec + + +class Entry(dict): + @property + def timestamp(self): + usec = self.get('__REALTIME_TIMESTAMP') + if usec is None: return None + return Timestamp(usec) - @staticmethod - def get_current(): - journal_args = ['journalctl', '-o', 'json', '-n', '1'] - with subprocess.Popen(journal_args, - bufsize=1, # line buffering - universal_newlines=True, - stdout=subprocess.PIPE) as jproc: - stdout, _ = jproc.communicate() - entry = json.loads(stdout) - return entry['__CURSOR'] - - -class Timestamps: - @staticmethod - def str2unix(string): - # systemd uses microsecond resolution - return int(string) / 10**6 - - def unix2print(str_or_int): - if not isinstance(str_or_int, float): - str_or_int = Timestamps.str2unix(str_or_int) - return datetime.datetime.utcfromtimestamp(str_or_int).strftime('%Y-%m-%d_%H:%M:%S') - - -class Journals: - @staticmethod - def read_logs(*args): - journal_args = [ - 'journalctl', - '-o', 'json', - '-u', 'kres*', - '-u', 'systemd-coredump*'] - journal_args += args - with subprocess.Popen(journal_args, - bufsize=1, # line buffering - universal_newlines=True, - stdout=subprocess.PIPE) as jproc: - for line in jproc.stdout: - yield json.loads(line) - - @staticmethod - def extract_logs(around_time, log_name): - start_time = around_time - TIMESPAN_BEFORE - end_time = around_time + TIMESPAN_AFTER - log_window = list(Journals.read_logs( - '--since=@{}'.format(start_time), - '--until=@{}'.format(end_time) - )) - with log_name.with_suffix('.json').open('w') as jsonf: - json.dump(log_window, jsonf, indent=4) - with log_name.with_suffix('.log').open('w') as logf: - logf.write('##### logs since {}\n'.format(Timestamps.unix2print(start_time))) - for entry in log_window: - entry_time = Timestamps.str2unix(entry['__REALTIME_TIMESTAMP']) - if entry_time == around_time: - logf.write('##### HERE #####\n') - logf.write('{t} {h} {prg}[{pid}]: {m}\n'.format( - t=Timestamps.unix2print(entry_time), - h=entry['_HOSTNAME'], - prg=( - entry.get('COREDUMP_UNIT') - or entry.get('UNIT') - or entry.get('_SYSTEMD_UNIT') - or entry['SYSLOG_IDENTIFIER'] - ), - pid=entry.get('COREDUMP_PID') or entry['_PID'], - m=entry['MESSAGE'] - ) - ) - logf.write('##### logs until {}\n'.format(Timestamps.unix2print(end_time))) + @property + def core_path(self): + filename = self.get('COREDUMP_FILENAME') + if filename is None: + return None + return pathlib.Path(filename) + + def get_first(self, *keys): + for key in keys: + try: + return self[key] + except KeyError: + continue + return None + + @property + def program(self): + return self.get_first('COREDUMP_UNIT', 'UNIT', '_SYSTEMD_UNIT', 'SYSLOG_IDENTIFIER') + + @property + def pid(self): + return self.get_first('COREDUMP_PID', '_PID') + + +def save_cursor(cursor): + if cursor is None: + return + CURSOR_DIR.mkdir(parents=True, exist_ok=True) + with CURSOR_PATH.open('w') as curfile: + curfile.write(cursor) + logging.info('log cursor saved into %s, next run will skip old logs', + CURSOR_PATH) + + +def load_cursor(): + try: + with CURSOR_PATH.open('r') as curfile: + logging.info('log cursor read from %s, skipping old logs', + CURSOR_PATH) + return curfile.read().strip() + except FileNotFoundError: + logging.info('log cursor file %s does not exist, parsing all logs', + CURSOR_PATH) + return None + + +def get_cursor(): + journal_args = ['journalctl', '-o', 'json', '-n', '1'] + with subprocess.Popen( + journal_args, + bufsize=1, # line buffering + universal_newlines=True, + stdout=subprocess.PIPE) as jproc: + stdout, _ = jproc.communicate() + data = json.loads(stdout) + entry = Entry(**data) + return entry.get('__CURSOR') + + +def read_journal(*args): + journal_args = [ + 'journalctl', + '-o', 'json', + '-u', 'kres*', + '-u', 'systemd-coredump*'] + journal_args += args + with subprocess.Popen( + journal_args, + bufsize=1, # line buffering + universal_newlines=True, + stdout=subprocess.PIPE) as jproc: + for line in jproc.stdout: + data = json.loads(line) + yield Entry(**data) + + +def extract_logs(around_time, log_name): + start_time = Timestamp(around_time.usec - TIMESPAN_BEFORE * 10**6) + end_time = Timestamp(around_time.usec + TIMESPAN_AFTER * 10**6) + log_window = list(read_journal( + '--since', '@{}'.format(start_time.unix), + '--until', '@{}'.format(end_time.unix))) + with log_name.with_suffix('.json').open('w') as jsonf: + json.dump(log_window, jsonf, indent=4) + with log_name.with_suffix('.log').open('w') as logf: + logf.write('##### logs since {}\n'.format(start_time)) + for entry in log_window: + if entry.timestamp == around_time: + logf.write('##### HERE #####\n') + logf.write('{t} {h} {prg}[{pid}]: {m}\n'.format( + t=entry.timestamp, + h=entry.get('_HOSTNAME'), + prg=entry.program, + pid=entry.pid, + m=entry.get('MESSAGE'))) + logf.write('##### logs until {}\n'.format(end_time)) def main(): logging.basicConfig(level=logging.INFO) if len(sys.argv) != 2: - sys.exit('Usage: %s '.format(sys.argv[0])) + sys.exit('Usage: {} '.format(sys.argv[0])) outdir = pathlib.Path(sys.argv[1]) outdir.mkdir(parents=True, exist_ok=True) - cursor_previous = Cursors.get_previous() - cursor_at_start = Cursors.get_current() + cursor_previous = load_cursor() + cursor_at_start = get_cursor() exit_times = [] coredumps = {} filter_args = [] - if cursor_previous: + if cursor_previous is not None: filter_args = ['--after-cursor', cursor_previous] - for entry in Journals.read_logs(*filter_args): + for entry in read_journal(*filter_args): if 'EXIT_CODE' in entry: - exit_time = Timestamps.str2unix(entry['__REALTIME_TIMESTAMP']) - logging.debug('exit@%s: %s', exit_time, entry) - exit_times.append(exit_time) + logging.debug('exit@%s: %s', entry.timestamp, entry) + exit_times.append(entry.timestamp) if 'COREDUMP_FILENAME' in entry: - core_path = pathlib.Path(entry['COREDUMP_FILENAME']) - core_time = Timestamps.str2unix(entry['__REALTIME_TIMESTAMP']) - logging.debug('coredump @ %s: %s', core_time, core_path) - coredumps[core_path] = core_time + logging.debug('coredump @ %s: %s', entry.timestamp, entry.core_path) + coredumps[entry.core_path] = entry.timestamp exit_times.sort() logging.debug('detected exits: %s', exit_times) for exit_time in exit_times: - Journals.extract_logs(exit_time, outdir / '{}'.format(Timestamps.unix2print(exit_time))) + extract_logs(exit_time, outdir / str(exit_time)) coredumps_missing = 0 logging.debug('detected coredumps: %s', coredumps) for core_path, core_time in coredumps.items(): core_name = core_path.name - timestamp = Timestamps.unix2print(core_time) - out_path_prefix = (outdir / timestamp) - Journals.extract_logs(core_time, out_path_prefix.with_suffix('.logs')) + out_path_prefix = (outdir / str(core_time)) + extract_logs(core_time, out_path_prefix.with_suffix('.logs')) try: shutil.copy( str(core_path), - str(out_path_prefix.with_suffix('.{}'.format(str(core_name))))) + str(out_path_prefix.with_suffix('.{}'.format(core_name)))) except FileNotFoundError as ex: logging.error('coredump file %s cannot be copied: %s', core_path, ex) coredumps_missing += 1 logging.info('wrote %d coredumps and %d logs snippets (%s coredumps missing)', len(coredumps) - coredumps_missing, len(exit_times), coredumps_missing) - Cursors.overwrite_previous(cursor_at_start) + save_cursor(cursor_at_start) + if __name__ == '__main__': main() -- 2.47.2