From: Petr Špaček Date: Fri, 14 Aug 2020 08:14:27 +0000 (+0200) Subject: script to gather data from systemd journal X-Git-Tag: v5.1.3~12^2~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=547b603f71ec11f4da3e32de8df9a77b50ecff57;p=thirdparty%2Fknot-resolver.git script to gather data from systemd journal --- diff --git a/scripts/bugreport-journals.py b/scripts/bugreport-journals.py new file mode 100755 index 000000000..dcbc12900 --- /dev/null +++ b/scripts/bugreport-journals.py @@ -0,0 +1,168 @@ +#!/usr/bin/python3 +""" +Collect sysmted-journald log entries around time of daemon exit and coredumps. +""" + +import datetime +import json +import logging +import os +import pathlib +import shutil +import subprocess +import sys + + +TIMESPAN_BEFORE = 600 # s +TIMESPAN_AFTER = TIMESPAN_BEFORE + + +class Cursors: + cursordir = pathlib.Path('/var/lib/knot-resolver') + path = cursordir / pathlib.Path('coredump_watcher.cursor') + + @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) + + @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) + return None + + @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))) + + +def main(): + logging.basicConfig(level=logging.INFO) + + if len(sys.argv) != 2: + sys.exit('Usage: %s '.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() + + exit_times = [] + coredumps = {} + filter_args = [] + if cursor_previous: + filter_args = ['--after-cursor', cursor_previous] + for entry in Journals.read_logs(*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) + 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 + + 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))) + + 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')) + try: + shutil.copy( + str(core_path), + str(out_path_prefix.with_suffix('.{}'.format(str(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) + +if __name__ == '__main__': + main()