URL: https://github.com/SSSD/sssd/pull/5712 Author: justin-stephenson Title: #5712: Health and Support Analyzer - Add request log parsing utility Action: synchronized
To pull the PR as Git branch: git remote add ghsssd https://github.com/SSSD/sssd git fetch ghsssd pull/5712/head:pr5712 git checkout pr5712
From 225f91087af3d0abb8d0c91811a8c1e305874a66 Mon Sep 17 00:00:00 2001 From: Justin Stephenson <jstep...@redhat.com> Date: Wed, 4 Aug 2021 14:57:55 +0000 Subject: [PATCH 1/4] DP: Log offline warning for REQ_TRACE tracking This allows the sssctl analyze parsing tool to report if the backend was offline when the request came in to the data provider. --- src/providers/data_provider/dp_request.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/providers/data_provider/dp_request.c b/src/providers/data_provider/dp_request.c index 077b361f3c..3cbd55c1ec 100644 --- a/src/providers/data_provider/dp_request.c +++ b/src/providers/data_provider/dp_request.c @@ -133,6 +133,10 @@ static errno_t dp_attach_req(struct dp_req *dp_req, SSS_REQ_TRACE_CID_DP_REQ(SSSDBG_TRACE_FUNC, dp_req->name, "New request. [%s CID #%u] Flags [%#.4x].", sender_name, cli_id, dp_flags); + if (be_is_offline(provider->be_ctx)) { + DEBUG(SSSDBG_TRACE_FUNC, "[CID #%u] Backend is offline! " \ + "Using cached data if available\n", cli_id); + } } else { SSS_REQ_TRACE_CID_DP_REQ(SSSDBG_TRACE_FUNC, dp_req->name, "New request. Flags [%#.4x].", From f67152712f30fef7abca494520ca32cacac03b55 Mon Sep 17 00:00:00 2001 From: Justin Stephenson <jstep...@redhat.com> Date: Fri, 1 Oct 2021 15:13:57 +0000 Subject: [PATCH 2/4] Responder: Log client uid that started a request --- src/responder/common/responder_common.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/responder/common/responder_common.c b/src/responder/common/responder_common.c index 3207e26e6f..7e145aa9b2 100644 --- a/src/responder/common/responder_common.c +++ b/src/responder/common/responder_common.c @@ -640,9 +640,9 @@ static void accept_fd_handler(struct tevent_context *ev, rctx->client_id_num++; DEBUG(SSSDBG_TRACE_FUNC, - "Client [CID #%u][cmd %s][%p][%d] connected%s!\n", - rctx->client_id_num, cctx->cmd_line, cctx, cctx->cfd, - accept_ctx->is_private ? " to privileged pipe" : ""); + "Client [CID #%u][cmd %s][uid %u][%p][%d] connected%s!\n", + rctx->client_id_num, cctx->cmd_line, cli_creds_get_uid(cctx->creds), + cctx, cctx->cfd, accept_ctx->is_private ? " to privileged pipe" : ""); return; } From 0a018653576715d8af13ec4eb6bc57791e1f2078 Mon Sep 17 00:00:00 2001 From: Justin Stephenson <jstep...@redhat.com> Date: Fri, 11 Jun 2021 11:04:59 -0400 Subject: [PATCH 3/4] TOOLS: Add sss_analyze utility Add log parsing tool which can be used to track requests across responder and backend logs. --- Makefile.am | 2 +- configure.ac | 1 + contrib/sssd.spec.in | 5 + src/tools/analyzer/Makefile.am | 16 ++ src/tools/analyzer/modules/__init__.py | 0 src/tools/analyzer/modules/request.py | 276 +++++++++++++++++++++++++ src/tools/analyzer/source_files.py | 76 +++++++ src/tools/analyzer/source_journald.py | 47 +++++ src/tools/analyzer/source_reader.py | 27 +++ src/tools/analyzer/sss_analyze.py | 27 +++ 10 files changed, 476 insertions(+), 1 deletion(-) create mode 100644 src/tools/analyzer/Makefile.am create mode 100644 src/tools/analyzer/modules/__init__.py create mode 100644 src/tools/analyzer/modules/request.py create mode 100644 src/tools/analyzer/source_files.py create mode 100644 src/tools/analyzer/source_journald.py create mode 100644 src/tools/analyzer/source_reader.py create mode 100755 src/tools/analyzer/sss_analyze.py diff --git a/Makefile.am b/Makefile.am index 6d84b082ec..c7c429965d 100644 --- a/Makefile.am +++ b/Makefile.am @@ -22,7 +22,7 @@ SUBDIRS += src/man endif SUBDIRS += . src/tests/cwrap src/tests/intg src/tests/test_CA \ - src/tests/test_ECC_CA + src/tests/test_ECC_CA src/tools/analyzer # Some old versions of automake don't define builddir builddir ?= . diff --git a/configure.ac b/configure.ac index c5c3a903b0..c5193fa545 100644 --- a/configure.ac +++ b/configure.ac @@ -531,6 +531,7 @@ AC_CONFIG_FILES([Makefile contrib/sssd.spec src/examples/rwtab src/doxy.config src/lib/sifp/sss_simpleifp.doxy src/config/setup.py src/systemtap/sssd.stp + src/tools/analyzer/Makefile src/config/SSSDConfig/__init__.py]) AC_CONFIG_FILES([sbus_generate.sh], [chmod +x sbus_generate.sh]) AC_OUTPUT diff --git a/contrib/sssd.spec.in b/contrib/sssd.spec.in index c8a4f62c7e..a9b7ecc5c6 100644 --- a/contrib/sssd.spec.in +++ b/contrib/sssd.spec.in @@ -213,6 +213,9 @@ Requires: sssd-common = %{version}-%{release} Requires: python3-sss = %{version}-%{release} Requires: python3-sssdconfig = %{version}-%{release} Requires: libsss_certmap = %{version}-%{release} +# required by sss_analyze +Requires: python3-systemd +Requires: python3-click Recommends: sssd-dbus %description tools @@ -525,6 +528,7 @@ autoreconf -ivf %make_build all docs runstatedir=%{_rundir} +%py3_shebang_fix src/tools/analyzer/sss_analyze.py sed -i -e 's:/usr/bin/python:/usr/bin/python3:' src/tools/sss_obfuscate %check @@ -854,6 +858,7 @@ done %{_sbindir}/sss_debuglevel %{_sbindir}/sss_seed %{_sbindir}/sssctl +%{python3_sitelib}/sssd/ %{_mandir}/man8/sss_obfuscate.8* %{_mandir}/man8/sss_override.8* %{_mandir}/man8/sss_debuglevel.8* diff --git a/src/tools/analyzer/Makefile.am b/src/tools/analyzer/Makefile.am new file mode 100644 index 0000000000..d9f82aa61a --- /dev/null +++ b/src/tools/analyzer/Makefile.am @@ -0,0 +1,16 @@ +pkgpythondir = $(python3dir)/sssd + +dist_pkgpython_SCRIPTS = \ + sss_analyze.py \ + $(NULL) + +dist_pkgpython_DATA = \ + source_files.py \ + source_journald.py \ + source_reader.py \ + $(NULL) + +modulesdir = $(pkgpythondir)/modules +dist_modules_DATA = \ + modules/request.py \ + $(NULL) diff --git a/src/tools/analyzer/modules/__init__.py b/src/tools/analyzer/modules/__init__.py new file mode 100644 index 0000000000..e69de29bb2 diff --git a/src/tools/analyzer/modules/request.py b/src/tools/analyzer/modules/request.py new file mode 100644 index 0000000000..098a9197bb --- /dev/null +++ b/src/tools/analyzer/modules/request.py @@ -0,0 +1,276 @@ +import re +import copy +import click +import logging + +from enum import Enum +from source_files import Files +from source_journald import Journald + +logger = logging.getLogger() + + +@click.group(help="Request module") +def request(): + pass + + +@request.command() +@click.option("-v", "--verbose", is_flag=True, help="Enables verbose output") +@click.option("--pam", is_flag=True, help="Filter only PAM requests") +@click.pass_obj +def list(ctx, verbose, pam): + analyzer = RequestAnalyzer() + source = analyzer.load(ctx) + analyzer.list_requests(source, verbose, pam) + + +@request.command() +@click.argument("cid", nargs=1, type=int, required=True) +@click.option("--merge", is_flag=True, help="Merge logs together sorted" + " by timestamp (requires debug_microseconds = True)") +@click.option("--cachereq", is_flag=True, help="Include cache request " + "related logs") +@click.option("--pam", is_flag=True, help="Track only PAM requests") +@click.pass_obj +def show(ctx, cid, merge, cachereq, pam): + analyzer = RequestAnalyzer() + source = analyzer.load(ctx) + analyzer.track_request(source, cid, merge, cachereq, pam) + + +class RequestAnalyzer: + """ + A request analyzer module, handles request tracking logic + and analysis. Parses input generated from a source Reader. + """ + consumed_logs = [] + done = "" + + def load(self, ctx): + """ + Load the appropriate source reader. + + Args: + ctx (click.ctx): command line state object + + Returns: + Instantiated source object + """ + if ctx.source == "journald": + import source_journald + source = Journald() + else: + source = Files(ctx.logdir) + return source + + def matched_line(self, source, patterns): + """ + Yield lines which match any number of patterns (OR) in + provided patterns list. + + Args: + source (Reader): source Reader object + Yields: + lines matching the provided pattern(s) + """ + for line in source: + for pattern in patterns: + re_obj = re.compile(pattern) + if re_obj.search(line): + if line.startswith(' * '): + continue + yield line + + def get_linked_ids(self, source, pattern, regex): + """ + Retrieve list of associated REQ_TRACE ids. Filter + only source lines by pattern, then parse out the + linked id with the provided regex. + + Args: + source (Reader): source Reader object + pattern (list of str): regex pattern(s) used for finding + linked ids + regex (str): regular expression used to extract linked id + + Returns: + List of linked ids discovered + """ + linked_ids = [] + for match in self.matched_line(source, pattern): + id_re = re.compile(regex) + match = id_re.search(match) + if match: + found = match.group(0) + linked_ids.append(found) + return linked_ids + + def consume_line(self, line, source, consume): + """ + Print or consume a line, if merge cli option is provided then consume + boolean is set to True + + Args: + line (str): line to process + source (Reader): source Reader object + consume (bool): If True, line is added to consume_logs + list, otherwise print line + + Returns: + True if line was processed, otherwise False + """ + found_results = True + if consume: + self.consumed_logs.append(line.rstrip(line[-1])) + else: + # files source includes newline + if isinstance(source, Files): + print(line, end='') + else: + print(line) + return found_results + + def print_formatted(self, line, verbose): + """ + Parse line and print formatted list_requests output + + Args: + line (str): line to parse + verbose (bool): If true, enable verbose output + """ + plugin = "" + name = "" + id = "" + + # exclude backtrace logs + if line.startswith(' * '): + return + fields = line.split("[") + cr_field = fields[2].split(":")[1] + cr = cr_field[5:] + if "refreshed" in line: + return + # CR Plugin name + if re.search("cache_req_send", line): + plugin = line.split('\'')[1] + # CR Input name + elif re.search("cache_req_process_input", line): + name = line.rsplit('[')[-1] + # CR Input id + elif re.search("cache_req_search_send", line): + id = line.rsplit()[-1] + # CID and client process name + else: + ts = line.split(")")[0] + ts = ts[1:] + fields = line.split("[") + cid = fields[3][5:-1] + cmd = fields[4][4:-1] + uid = fields[5][4:-1] + if not uid.isnumeric(): + uid = fields[6][4:-1] + print(f'{ts}: [uid {uid}] CID #{cid}: {cmd}') + + if verbose: + if plugin: + print(" - " + plugin) + if name: + if cr not in self.done: + print(" - " + name[:-2]) + self.done = cr + if id: + if cr not in self.done: + print(" - " + id) + self.done = cr + + def list_requests(self, source, verbose, pam): + """ + List component (default: NSS) responder requests + + Args: + line (str): line to process + source (Reader): source Reader object + verbose (bool): True if --verbose cli option is provided, enables + verbose output + pam (bool): True if --pam cli option is provided, list requests + in the PAM responder only + """ + component = source.Component.NSS + resp = "nss" + patterns = ['\[cmd'] + patterns.append("(cache_req_send|cache_req_process_input|" + "cache_req_search_send)") + consume = True + if pam: + component = source.Component.PAM + resp = "pam" + + logger.info(f"******** Listing {resp} client requests ********") + source.set_component(component) + self.done = "" + # For each CID + for line in self.matched_line(source, patterns): + if isinstance(source, Journald): + print(line) + else: + self.print_formatted(line, verbose) + + def track_request(self, source, cid, merge, cachereq, pam): + """ + Print Logs pertaining to individual SSSD client request + + Args: + source (Reader): source Reader object + cid (int): client ID number to show + merge (bool): True when --merge is provided, merge logs together + by timestamp + pam (bool): True if --pam cli option is provided, track requests + in the PAM responder + """ + resp_results = False + be_results = False + component = source.Component.NSS + resp = "nss" + pattern = [f'REQ_TRACE.*\[CID #{cid}\\]'] + pattern.append(f"\[CID #{cid}\\].*connected") + + if pam: + component = source.Component.PAM + resp = "pam" + pam_data_regex = f'pam_print_data.*\[CID #{cid}\]' + + logger.info(f"******** Checking {resp} responder for Client ID" + f" {cid} *******") + source.set_component(component) + if cachereq: + cr_id_regex = 'CR #[0-9]+' + cr_ids = self.get_linked_ids(source, pattern, cr_id_regex) + [pattern.append(f'{id}\:') for id in cr_ids] + + for match in self.matched_line(source, pattern): + resp_results = self.consume_line(match, source, merge) + + logger.info(f"********* Checking Backend for Client ID {cid} ********") + pattern = [f'REQ_TRACE.*\[sssd.{resp} CID #{cid}\]'] + source.set_component(source.Component.BE) + + be_id_regex = '\[RID#[0-9]+\]' + be_ids = self.get_linked_ids(source, pattern, be_id_regex) + + pattern.clear() + [pattern.append(f'\\{id}') for id in be_ids] + + if pam: + pattern.append(pam_data_regex) + for match in self.matched_line(source, pattern): + be_results = self.consume_line(match, source, merge) + + if merge: + # sort by date/timestamp + sorted_list = sorted(self.consumed_logs, + key=lambda s: s.split(')')[0]) + for entry in sorted_list: + print(entry) + if not resp_results and not be_results: + logger.warn(f"ID {cid} not found in logs!") diff --git a/src/tools/analyzer/source_files.py b/src/tools/analyzer/source_files.py new file mode 100644 index 0000000000..df87f92fbd --- /dev/null +++ b/src/tools/analyzer/source_files.py @@ -0,0 +1,76 @@ +from enum import Enum +import configparser +from os import listdir +from os.path import isfile, join +import glob +import logging + +from source_reader import Reader + +logger = logging.getLogger() + + +class Files(Reader): + """ + A class used to represent a Log Files Reader + + Args: + path -- the path where SSSD logs are to + be read (default /var/log/sssd/) + """ + + def __init__(self, path): + super().__init__() + self.log_files = [] + self.path = self.resolve_path(path) + self.domains = self.get_domain_logfiles() + + def __iter__(self): + """ + Yields: + str: The next line in the log file + """ + for files in self.log_files: + try: + with open(files) as file: + for line in file: + yield line + except FileNotFoundError as err: + logger.warning("Could not find domain log file, skipping") + logger.warning(err) + continue + + def resolve_path(self, path): + if path.endswith("/"): + return path + else: + return path + "/" + + def get_domain_logfiles(self): + """ Retrieve list of SSSD log files, exclude rotated (.gz) files """ + domain_files = [] + exclude_list = ["ifp", "nss", "pam", "sudo", "autofs", + "ssh", "pac", "kcm", ".gz"] + file_list = glob.glob(self.path + "sssd_*") + for file in file_list: + if not any(s in file for s in exclude_list): + domain_files.append(file) + + return domain_files + + def set_component(self, component): + """ + Switch the reader to interact with a certain SSSD component + NSS, PAM, BE + """ + self.log_files = [] + if component == self.Component.NSS: + self.log_files.append(self.path + "sssd_nss.log") + elif component == self.Component.PAM: + self.log_files.append(self.path + "sssd_pam.log") + elif component == self.Component.BE: + if not self.domains: + raise IOError + # error: No domains found? + for dom in self.domains: + self.log_files.append(dom) diff --git a/src/tools/analyzer/source_journald.py b/src/tools/analyzer/source_journald.py new file mode 100644 index 0000000000..86d81d4854 --- /dev/null +++ b/src/tools/analyzer/source_journald.py @@ -0,0 +1,47 @@ +from systemd import journal +from source_reader import Reader + +from enum import Enum + +_EXE_PREFIX = "/usr/libexec/sssd/" +_NSS_MATCH = _EXE_PREFIX + "sssd_nss" +_PAM_MATCH = _EXE_PREFIX + "sssd_pam" +_BE_MATCH = _EXE_PREFIX + "sssd_be" + + +class Journald(Reader): + """ + A class used to represent a Journald Reader + """ + def __init__(self): + super().__init__() + self.reader = journal.Reader() + self.reader.this_boot() + self.reader.seek_head() + + def __iter__(self): + """ + Yields: + str: The next journal entry message, with timestamp if found + """ + self.reader.seek_head() + for entry in self.reader: + ts = entry['__REALTIME_TIMESTAMP'] + msg = entry['MESSAGE'] + if ts: + yield f'{ts}: {msg}' + else: + yield msg + + def set_component(self, component): + """ + Switch the reader to interact with a certain SSSD component + NSS, PAM, BE + """ + self.reader.flush_matches() + if component == self.Component.NSS: + self.reader.add_match(_EXE=_NSS_MATCH) + elif component == self.Component.PAM: + self.reader.add_match(_EXE=_PAM_MATCH) + elif component == self.Component.BE: + self.reader.add_match(_EXE=_BE_MATCH) diff --git a/src/tools/analyzer/source_reader.py b/src/tools/analyzer/source_reader.py new file mode 100644 index 0000000000..10d2d37699 --- /dev/null +++ b/src/tools/analyzer/source_reader.py @@ -0,0 +1,27 @@ +from enum import Enum + +from abc import ABC, abstractmethod + + +class Reader(ABC): + """ + An abstract class used to represent a source Reader + """ + + class Component(Enum): + """ SSSD component to enable for reading """ + NSS = 1 # NSS Responder + PAM = 2 # PAM Responder + BE = 3 # Backend + + @abstractmethod + def __init__(self): + pass + + @abstractmethod + def __iter__(self): + pass + + @abstractmethod + def set_component(self): + pass diff --git a/src/tools/analyzer/sss_analyze.py b/src/tools/analyzer/sss_analyze.py new file mode 100755 index 0000000000..89684a3f75 --- /dev/null +++ b/src/tools/analyzer/sss_analyze.py @@ -0,0 +1,27 @@ +#!/usr/bin/env python + +import click + +import source_files + +from modules import request + + +class Analyzer(object): + def __init__(self, source="files", logdir="/var/log/sssd/"): + self.source = source + self.logdir = logdir + + +@click.group(help="Analyzer tool to assist with SSSD Log parsing") +@click.option('--source', default='files') +@click.option('--logdir', default='/var/log/sssd/', help="SSSD Log directory " + "to parse log files from") +@click.pass_context +def cli(ctx, source, logdir): + ctx.obj = Analyzer(source, logdir) + + +if __name__ == '__main__': + cli.add_command(request.request) + cli() From 8b1d6200a28177ab8bd225d6e0e1157510fee16c Mon Sep 17 00:00:00 2001 From: Justin Stephenson <jstep...@redhat.com> Date: Fri, 21 May 2021 14:42:41 -0400 Subject: [PATCH 4/4] SSSCTL: Add analyze command Wrapper for sss_analyze Print a message about limited functionality when tevent chain ID support is not built. --- Makefile.am | 1 + src/tools/sssctl/sssctl.c | 1 + src/tools/sssctl/sssctl.h | 4 ++++ src/tools/sssctl/sssctl_logs.c | 29 +++++++++++++++++++++++++++++ 4 files changed, 35 insertions(+) diff --git a/Makefile.am b/Makefile.am index c7c429965d..9b287f5f4f 100644 --- a/Makefile.am +++ b/Makefile.am @@ -1983,6 +1983,7 @@ sssctl_LDADD = \ $(NULL) sssctl_CFLAGS = \ $(AM_CFLAGS) \ + -DPYTHONDIR_PATH=\"$(python3dir)/sssd\" \ $(NULL) if BUILD_SUDO diff --git a/src/tools/sssctl/sssctl.c b/src/tools/sssctl/sssctl.c index 8adaf30910..3816125ad3 100644 --- a/src/tools/sssctl/sssctl.c +++ b/src/tools/sssctl/sssctl.c @@ -296,6 +296,7 @@ int main(int argc, const char **argv) SSS_TOOL_COMMAND("logs-remove", "Remove existing SSSD log files", 0, sssctl_logs_remove), SSS_TOOL_COMMAND("logs-fetch", "Archive SSSD log files in tarball", 0, sssctl_logs_fetch), SSS_TOOL_COMMAND("debug-level", "Change SSSD debug level", 0, sssctl_debug_level), + SSS_TOOL_COMMAND("analyze", "Analyze logged data", 0, sssctl_analyze), #ifdef HAVE_LIBINI_CONFIG_V1_3 SSS_TOOL_DELIMITER("Configuration files tools:"), SSS_TOOL_COMMAND_FLAGS("config-check", "Perform static analysis of SSSD configuration", 0, sssctl_config_check, SSS_TOOL_FLAG_SKIP_CMD_INIT), diff --git a/src/tools/sssctl/sssctl.h b/src/tools/sssctl/sssctl.h index 599ef65196..c827bb8789 100644 --- a/src/tools/sssctl/sssctl.h +++ b/src/tools/sssctl/sssctl.h @@ -96,6 +96,10 @@ errno_t sssctl_debug_level(struct sss_cmdline *cmdline, struct sss_tool_ctx *tool_ctx, void *pvt); +errno_t sssctl_analyze(struct sss_cmdline *cmdline, + struct sss_tool_ctx *tool_ctx, + void *pvt); + errno_t sssctl_user_show(struct sss_cmdline *cmdline, struct sss_tool_ctx *tool_ctx, void *pvt); diff --git a/src/tools/sssctl/sssctl_logs.c b/src/tools/sssctl/sssctl_logs.c index ebb2c4571c..b98cd68fec 100644 --- a/src/tools/sssctl/sssctl_logs.c +++ b/src/tools/sssctl/sssctl_logs.c @@ -41,6 +41,7 @@ #define LOG_FILE(file) " " LOG_PATH "/" file #define LOG_FILES LOG_FILE("*.log") +#define SSS_ANALYZE PYTHONDIR_PATH"/sss_analyze.py" #define CHECK(expr, done, msg) do { \ if (expr) { \ @@ -388,3 +389,31 @@ errno_t sssctl_debug_level(struct sss_cmdline *cmdline, talloc_free(ctx); return ret; } + +errno_t sssctl_analyze(struct sss_cmdline *cmdline, + struct sss_tool_ctx *tool_ctx, + void *pvt) +{ + errno_t ret; + +#ifndef BUILD_CHAIN_ID + PRINT("NOTE: Tevent chain ID support missing, request analysis will be limited.\n"); + PRINT("It is recommended to use the --logdir option against tevent chain ID " + "supported SSSD logs.\n"); +#endif + const char **args = talloc_array_size(tool_ctx, + sizeof(char *), + cmdline->argc + 2); + if (!args) { + return ENOMEM; + } + memcpy(&args[1], cmdline->argv, sizeof(char *) * cmdline->argc); + args[0] = SSS_ANALYZE; + args[cmdline->argc + 1] = NULL; + + ret = sssctl_run_command(args); + + talloc_free(args); + + return ret; +}
_______________________________________________ sssd-devel mailing list -- sssd-devel@lists.fedorahosted.org To unsubscribe send an email to sssd-devel-le...@lists.fedorahosted.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/sssd-devel@lists.fedorahosted.org Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure