From 062321e04cb96165fc96525dbb7e4a6996402fed Mon Sep 17 00:00:00 2001 From: William Brown Date: Wed, 27 Apr 2016 14:13:02 +1000 Subject: [PATCH] Ticket 48434 - lib389 logging tools Bug Description: Many tests or error cases need to be able to check the log of the system to determine if the issue has occured on not. Fix Description: This adds an initial construction of a log parser and tools to interact with access and error logs so that we can use these effectively in tests. https://fedorahosted.org/389/ticket/48434 Author: wibrown Review by: ??? --- lib389/__init__.py | 3 ++ lib389/dirsrv_log.py | 112 ++++++++++++++++++++++++++++++++++++++++ lib389/properties.py | 15 ++++++ lib389/tests/dirsrv_log_test.py | 83 +++++++++++++++++++++++++++++ 4 files changed, 213 insertions(+) create mode 100644 lib389/dirsrv_log.py create mode 100644 lib389/tests/dirsrv_log_test.py diff --git a/lib389/__init__.py b/lib389/__init__.py index 20893ec..2d5165b 100644 --- a/lib389/__init__.py +++ b/lib389/__init__.py @@ -368,6 +368,7 @@ class DirSrv(SimpleLDAPObject): from lib389.aci import Aci from lib389.monitor import Monitor from lib389.nss_ssl import NssSsl + from lib389.dirsrv_log import DirsrvAccessLog, DirsrvErrorLog self.agreement = Agreement(self) self.replica = Replica(self) @@ -384,6 +385,8 @@ class DirSrv(SimpleLDAPObject): self.monitor = Monitor(self) # Do we have a certdb path? self.nss_ssl = NssSsl(self) + self.ds_access_log = DirsrvAccessLog(self) + self.ds_error_log = DirsrvErrorLog(self) def __init__(self, verbose=False, timeout=10): """ diff --git a/lib389/dirsrv_log.py b/lib389/dirsrv_log.py new file mode 100644 index 0000000..61d7e65 --- /dev/null +++ b/lib389/dirsrv_log.py @@ -0,0 +1,112 @@ +# --- BEGIN COPYRIGHT BLOCK --- +# Copyright (C) 2016 Red Hat, Inc. +# All rights reserved. +# +# License: GPL (version 3 or any later version). +# See LICENSE for details. +# --- END COPYRIGHT BLOCK --- + +"""Helpers for managing the directory server internal logs. +""" + +import re +from lib389._constants import DN_CONFIG +from lib389.properties import LOG_ACCESS_PATH, LOG_ERROR_PATH + +# Because many of these settings can change live, we need to check for certain +# attributes all the time. + +class DirsrvLog(object): + def __init__(self, dirsrv): + self.dirsrv = dirsrv + self.log = self.dirsrv.log + + def _get_log_attr(self, attr): + return self.dirsrv.getEntry(DN_CONFIG).__getattr__(attr) + + def _get_log_path(self): + return self._get_log_attr(self.log_path_attr) + + def readlines(self): + """ + Returns an array of all the lines in the log. + Will likely be very slow. Try using match instead. + """ + lines = [] + self.lpath = self._get_log_path() + if self.lpath is not None: + # Open the log + with open(self.lpath, 'r') as lf: + lines = lf.readlines() + # return a readlines fn? + return lines + + def match(self, pattern): + results = [] + prog = re.compile(pattern) + self.lpath = self._get_log_path() + if self.lpath is not None: + with open(self.lpath, 'r') as lf: + for line in lf: + mres = prog.match(line) + if mres: + results.append(line) + ## do a read lines, then match with the associated RE. + return results + +class DirsrvAccessLog(DirsrvLog): + def __init__(self, dirsrv): + super(DirsrvAccessLog, self).__init__(dirsrv) + self.log_path_attr = LOG_ACCESS_PATH + ## We precompile our regex for parse_line to make it faster. + self.prog_m1 = re.compile('^(?P\[.*\])\sconn=(?P\d*)\sop=(?P\d*)\s(?P\w*)\s(?P.*)') + self.prog_con = re.compile('^(?P\[.*\])\sconn=(?P\d*)\sfd=(?P\d*)\sslot=(?P\d*)\sconnection\sfrom\s(?P[^\s]*)\sto\s(?P[^\s]*)') + self.prog_discon = re.compile('^(?P\[.*\])\sconn=(?P\d*)\sop=(?P\d*)\sfd=(?P\d*)\s(?Pclosed)\s-\s(?P\w*)') + + def parse_line(self, line): + """ + This knows how to break up an access log line into the specific fields. + """ + line = line.strip() + action = { + 'action': 'CONNECT' + } + # First, pull some well known info out. + if self.dirsrv.verbose: + self.log.info("--> %s " % line) + m1 = self.prog_m1.match(line) + if m1: + action.update(m1.groupdict()) + # Do more parsing. + # Specifically, we need to break up action.rem based on action.action. + + con = self.prog_con.match(line) + if con: + action.update(con.groupdict()) + + discon = self.prog_discon.match(line) + if discon: + action.update(discon.groupdict()) + action['action'] = 'DISCONNECT' + + if self.dirsrv.verbose: + self.log.info(action) + return action + + def parse_lines(self, lines): + return map(self.parse_line, lines) + + +class DirsrvErrorLog(DirsrvLog): + def __init__(self, dirsrv): + super(DirsrvErrorLog, self).__init__(dirsrv) + self.log_path_attr = LOG_ERROR_PATH + self.prog_m1 = re.compile('^(?P\[.*\])\s(?P.*)') + + + def parse_line(self, line): + line = line.strip() + return self.prog_m1.match(line).groupdict() + + def parse_lines(self, line): + return map(self.parse_line, lines) diff --git a/lib389/properties.py b/lib389/properties.py index 26f2349..9f5175d 100644 --- a/lib389/properties.py +++ b/lib389/properties.py @@ -446,6 +446,21 @@ TASK_TOMB_STRIP = "strip-csn" EXPORT_REPL_INFO = "repl-info" +#################################### +# +# Properties related to logging. +# +#################################### + +LOG_ACCESS_ENABLED = "nsslapd-accesslog-logging-enabled" +LOG_ACCESS_LEVEL = "nsslapd-accesslog-level" +LOG_ACCESS_PATH = "nsslapd-accesslog" + +LOG_ERROR_ENABLED = "nsslapd-errorlog-logging-enabled" +LOG_ERROR_LEVEL = "nsslapd-errorlog-level" +LOG_ERROR_PATH = "nsslapd-errorlog" + + def rawProperty(prop): ''' Return the string 'prop' without the heading '+'/'-' diff --git a/lib389/tests/dirsrv_log_test.py b/lib389/tests/dirsrv_log_test.py new file mode 100644 index 0000000..45ab166 --- /dev/null +++ b/lib389/tests/dirsrv_log_test.py @@ -0,0 +1,83 @@ +# --- BEGIN COPYRIGHT BLOCK --- +# Copyright (C) 2015 Red Hat, Inc. +# All rights reserved. +# +# License: GPL (version 3 or any later version). +# See LICENSE for details. +# --- END COPYRIGHT BLOCK --- +# +from lib389._constants import * +from lib389 import DirSrv, Entry +import pytest +import time + +INSTANCE_PORT = 54321 +INSTANCE_SERVERID = 'loggingtest' + + +class TopologyStandalone(object): + def __init__(self, standalone): + standalone.open() + self.standalone = standalone + + +@pytest.fixture(scope="module") +def topology(request): + standalone = DirSrv(verbose=False) + standalone.log.debug("Instance allocated") + args = {SER_HOST: LOCALHOST, + SER_PORT: INSTANCE_PORT, + # SER_DEPLOYED_DIR: INSTANCE_PREFIX, + SER_SERVERID_PROP: INSTANCE_SERVERID} + standalone.allocate(args) + if standalone.exists(): + standalone.delete() + standalone.create() + standalone.open() + + def fin(): + standalone.delete() + request.addfinalizer(fin) + + return TopologyStandalone(standalone) + + +def test_access_log(topology): + """Check the parsing of the access log""" + # We have to wait for time to elapse for the access log to be flushed. + time.sleep(60) + access_lines = topology.standalone.ds_access_log.readlines() + assert(len(access_lines) > 0) + access_lines = topology.standalone.ds_access_log.match('.*fd=.*') + assert(len(access_lines) > 0) + # Test the line parser in a basic way. + assert( + topology.standalone.ds_access_log.parse_line('[27/Apr/2016:12:49:49.726093186 +1000] conn=1 fd=64 slot=64 connection from ::1 to ::1') == + {'slot': '64', 'remote': '::1', 'action': 'CONNECT', 'timestamp': '[27/Apr/2016:12:49:49.726093186 +1000]', 'fd': '64', 'conn': '1', 'local': '::1'} + ) + assert( + topology.standalone.ds_access_log.parse_line('[27/Apr/2016:12:49:49.727235997 +1000] conn=1 op=2 SRCH base="cn=config" scope=0 filter="(objectClass=*)" attrs="nsslapd-instancedir nsslapd-errorlog nsslapd-accesslog nsslapd-auditlog nsslapd-certdir nsslapd-schemadir nsslapd-bakdir nsslapd-ldifdir"') == + {'rem': 'base="cn=config" scope=0 filter="(objectClass=*)" attrs="nsslapd-instancedir nsslapd-errorlog nsslapd-accesslog nsslapd-auditlog nsslapd-certdir nsslapd-schemadir nsslapd-bakdir nsslapd-ldifdir"', 'action': 'SRCH', 'timestamp': '[27/Apr/2016:12:49:49.727235997 +1000]', 'conn': '1', 'op': '2'} + ) + assert( + topology.standalone.ds_access_log.parse_line('[27/Apr/2016:12:49:49.736297002 +1000] conn=1 op=4 fd=64 closed - U1') == + {'status': 'U1', 'fd': '64', 'action': 'closed', 'timestamp': '[27/Apr/2016:12:49:49.736297002 +1000]', 'conn': '1', 'op': '4'} + ) + +def test_error_log(topology): + """Check the parsing of the error log""" + # No need to sleep, it's not buffered. + error_lines = topology.standalone.ds_error_log.readlines() + assert(len(error_lines) > 0) + error_lines = topology.standalone.ds_error_log.match('.*started.*') + assert(len(error_lines) > 0) + + assert( + topology.standalone.ds_error_log.parse_line('[27/Apr/2016:13:46:35.775670167 +1000] slapd started. Listening on All Interfaces port 54321 for LDAP requests') == + {'timestamp': '[27/Apr/2016:13:46:35.775670167 +1000]', 'message': 'slapd started. Listening on All Interfaces port 54321 for LDAP requests'} + ) + + +if __name__ == "__main__": + CURRENT_FILE = os.path.realpath(__file__) + pytest.main("-s -vv %s" % CURRENT_FILE) -- 2.5.5