Add 3 unittests with fixed log file contents
authorChristian Herdtweck <christian.herdtweck@intra2net.com>
Tue, 8 Nov 2022 10:37:09 +0000 (11:37 +0100)
committerChristian Herdtweck <christian.herdtweck@intra2net.com>
Tue, 8 Nov 2022 10:46:35 +0000 (11:46 +0100)
Add some stability/reliability/reproducability to log parsing unit tests.

Also: fix type documentation in LogParser doc string

src/log_read.py
test/test_log_read.py

index ca47eb9..eeca819 100644 (file)
@@ -363,8 +363,9 @@ class LogParser(LineReader):
         """
         Create a LogParser.
 
-        :param str log_file: name of log file to parse (required!)
-        :param pattern: regexp to split log lines; None (default) to return
+        :param log_file: source of log lines to parse
+        :type log_file: see arg `sources` of constructor of :py:class:`IterativeReader`
+        :param pattern: regexp to parse log lines; None (default) to return
                         line as they are
         :type pattern: str or None (default)
         """
index 68c9160..d994971 100644 (file)
@@ -257,6 +257,105 @@ class LogReadTester(unittest.TestCase):
                                                                 line_read))
                     self.assertEqual(line_expected, line_read)
 
+    def test_parse_syslog_lines(self):
+        """Test parsing a few fixed lines of syslog"""
+        syslog_lines = """
+            Nov  8 08:10:01 system-name rsyslogd:  [origin software="rsyslogd" swVersion="8.39.0" x-pid="1968" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
+            Nov  8 08:10:12 system-name squid[2762]: Starting new redirector helpers...#012    current master transaction: master58
+            Nov  8 08:10:28 system-name pop30[3922]: counts: retr=<0> top=<0> dele=<0>
+            Nov  8 08:10:43 system-name pop3loc[3923]: counts: retr=<0> top=<0> dele=<0>
+            Nov  8 08:10:44 system-name pingcheck[3004]: Status (0 down, limit=4, notify up now): report link up?
+            Nov  8 08:10:44 system-name connd[2917]: [subsys_pingcheck] received notification that connection for id 1 is online
+            Nov  8 08:10:44 system-name connd[2917]: [subsys_pingcheck] Connection [ConnInfo P1 (connection name): online] was confirmed online
+            Nov  8 08:10:44 system-name connd[2917]: [connection_manager] Confirm that provider "P1" is online
+            Nov  8 08:11:01 system-name mon[3563]: failure for intranator dirwatchd 1667891461 (NO SUMMARY)
+            Nov  8 08:11:04 system-name lmtpunix[3962]: Delivered: <cmu-lmtpd-3962-1667891464-0@system-name.m.i2n> to mailbox: user.cyrus as uid: 49792
+            Nov  8 08:11:04 system-name lmtpunix[3962]: USAGE cyrus user: 0.000000 sys: 0.006803
+            Nov  8 08:11:20 system-name pop30[3982]: counts: retr=<0> top=<0> dele=<0>
+            Oct 21 07:52:39 system-name avupdate[3671]: successfully installed new antivirus database
+            Oct 21 07:52:39 system-name savapi_version_info[3973]: AVE=8.3.64.214, VDF=8.19.26.110, Released=21.10.2022 05:39
+            Oct 21 07:52:39 system-name connd[3180]: [connection_manager] online mode set to always online
+            Oct 21 07:52:47 system-name kernel: REJECT local IN=eth0 OUT= MACSRC=68:4f:64:75:7b:82 MACDST=01:00:5e:00:00:01 MACPROTO=0800 SRC=123.45.67.89 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=34431 PROTO=ICMP TYPE=9 CODE=0 
+            Oct 21 07:52:54 system-name lmtpunix[2715]: Delivered: <cmu-lmtpd-2715-1666331574-0@system-name.m.i2n> to mailbox: user.cyrus as uid: 46558
+            Oct 21 07:52:54 system-name lmtpunix[2715]: USAGE cyrus user: 0.010564 sys: 0.000000
+            Oct 21 07:53:08 system-name pop30[2703]: counts: retr=<0> top=<0> dele=<0>
+            Oct 21 07:53:08 system-name pop3loc[2701]: counts: retr=<0> top=<0> dele=<0>
+            Oct 21 07:53:30 system-name ntpd[3701]: adjusting local clock by -0.943974s
+            Oct 21 07:54:15 system-name keymakerd[3206]: [acmeautorenew] Starting auto renew check. @acmeautorenew#285
+            Oct 21 07:54:15 system-name keymakerd[3206]: [acmeautorenew] Finishing auto renew thread. @acmeautorenew#206
+            Oct 21 07:54:23 system-name pop3loc[2701]: counts: retr=<0> top=<0> dele=<0>
+            Oct 21 07:54:41 system-name pop30[2703]: counts: retr=<0> top=<0> dele=<0>
+            Oct 21 07:54:51 system-name squid[3025]: Starting new redirector helpers...#012    current master transaction: master54
+            Oct 21 07:54:55 system-name lmtpunix[3997]: Delivered: <cmu-lmtpd-3997-1666331695-0@system-name.m.i2n> to mailbox: user.cyrus as uid: 46559
+            Oct 21 07:54:55 system-name lmtpunix[3997]: USAGE cyrus user: 0.002022 sys: 0.005926
+            """
+        lines = [line.lstrip() for line in syslog_lines.splitlines() if line.lstrip()]
+        LogFileWriter(self.temp_file, lines, n_writes=len(lines)).start()
+        with open(self.temp_file, 'rt') as file_handle:
+            parser = LogParser(file_handle, SYS_LOG_PATTERN)
+            for _, data, _ in parser:
+                self.assertIsNotNone(data, f"Failed to parse {parser.last_unparsed_line}")
+
+    def test_parse_proxy_lines(self):
+        proxy_lines = """
+            1667901672.645      0 127.0.0.1 NONE_NONE/000 0 - error:transaction-end-before-headers - HIER_NONE/- - -
+            1667901792.812      0 127.0.0.1 NONE_NONE/000 0 - error:transaction-end-before-headers - HIER_NONE/- - -
+            1667901912.997      0 127.0.0.1 NONE_NONE/000 0 - error:transaction-end-before-headers - HIER_NONE/- - -
+            1667902032.168      0 127.0.0.1 NONE_NONE/000 0 - error:transaction-end-before-headers - HIER_NONE/- - -
+            1667902055.130    571 192.168.1.1 TCP_TUNNEL/200 10403 CONNECT apod.nasa.gov:443 - HIER_DIRECT/apod.nasa.gov - -
+            1667902063.333    969 192.168.1.1 TCP_TUNNEL/200 174425 CONNECT www.startpage.com:443 - HIER_DIRECT/www.startpage.com - -
+            1667902063.352     17 192.168.1.1 TCP_TUNNEL/200 39 CONNECT www.startpage.com:443 - HIER_DIRECT/www.startpage.com - -
+            1667902063.539     24 192.168.1.1 TCP_TUNNEL/200 39 CONNECT www.startpage.com:443 - HIER_DIRECT/www.startpage.com - -
+            1667902063.545    207 192.168.1.1 TCP_TUNNEL/200 1720 CONNECT www.startpage.com:443 - HIER_DIRECT/www.startpage.com - -
+            1667902064.141    611 192.168.1.1 TCP_TUNNEL/200 10100 CONNECT www.startpage.com:443 - HIER_DIRECT/www.startpage.com - -
+            1667902072.816    974 192.168.1.1 TCP_MISS/200 981 POST http://r3.o.lencr.org/ - FIRSTUP_PARENT/127.0.0.1 application/ocsp-response -
+            1667902089.338  16331 192.168.1.1 TCP_TUNNEL/200 103739 CONNECT www.roma-pizza-tuebingen.de:443 - HIER_DIRECT/www.roma-pizza-tuebingen.de - -
+            1667902089.339  16332 192.168.1.1 TCP_TUNNEL/200 49795 CONNECT www.roma-pizza-tuebingen.de:443 - HIER_DIRECT/www.roma-pizza-tuebingen.de - -
+            1667902089.339  16330 192.168.1.1 TCP_TUNNEL/200 24641 CONNECT www.roma-pizza-tuebingen.de:443 - HIER_DIRECT/www.roma-pizza-tuebingen.de - -
+            1667902105.718      0 192.168.1.1 NONE_NONE/000 0 - error:transaction-end-before-headers - HIER_NONE/- - -
+            1667902152.347      0 127.0.0.1 NONE_NONE/000 0 - error:transaction-end-before-headers - HIER_NONE/- - -
+            """
+        lines = [line.lstrip() for line in proxy_lines.splitlines() if line.lstrip()]
+        LogFileWriter(self.temp_file, lines, n_writes=len(lines)).start()
+        with open(self.temp_file, 'rt') as file_handle:
+            parser = LogParser(file_handle, PROXY_LOG_PATTERN)
+            for _, data, _ in parser:
+                self.assertIsNotNone(data, f"Failed to parse {parser.last_unparsed_line}")
+
+    def test_parse_maillog_lines(self):
+        mail_lines = """
+                Nov  7 10:07:33 system-name amavis[1]: SA info: rules: meta test I2N_RAZOR_ADJUST_4 has dependency 'RAZOR2_CF_RANGE_E8_51_100' with a zero score
+                Nov  7 10:07:33 system-name amavis[1]: SpamControl: init_pre_fork on SpamAssassin done
+                Nov  7 10:07:35 system-name quarantined[3574]: quarantined version 0.15 (build Jun 28 2022 17:26:39) up and running
+                Nov  7 10:07:52 system-name mailreconfig[3713]: called by sh[3712]|generate[3663], mode update, changed files: aliases,recipients
+                Nov  7 10:07:53 system-name postfix/postfix-script[3724]: refreshing the Postfix mail system
+                Nov  7 10:07:53 system-name postfix/master[2548]: reload -- version 3.3.22, configuration /etc/postfix
+                Nov  7 10:08:07 system-name mailreconfig[3851]: called by sh[3850]|generate[3804], mode update, changed files: aliases,recipients
+                Nov  7 10:08:07 system-name postfix/postfix-script[3862]: refreshing the Postfix mail system
+                Nov  7 10:08:07 system-name postfix/master[2548]: reload -- version 3.3.22, configuration /etc/postfix
+                Nov  7 10:08:11 system-name postfix/smtpd[3933]: connect from system-name.net.lan[127.0.0.1]
+                Nov  7 10:08:11 system-name postfix/smtpd[3933]: D9C626B: client=system-name.net.lan[127.0.0.1]
+                Nov  7 10:08:11 system-name postfix/cleanup[3936]: D9C626B: message-id=<20221107090811.D9C626B@system-name.net.lan>
+                Nov  7 10:08:11 system-name postfix/qmgr[3868]: D9C626B: from=<test-sender@system-name.net.lan>, size=10888, nrcpt=1 (queue active)
+                Nov  7 10:08:11 system-name postfix/smtpd[3933]: disconnect from system-name.net.lan[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
+                Nov  7 10:08:11 system-name postfix/smtpd[3933]: connect from system-name.net.lan[127.0.0.1]
+                Nov  7 10:08:11 system-name postfix/smtpd[3933]: E59146D: client=system-name.net.lan[127.0.0.1]
+                Nov  7 10:08:11 system-name postfix/cleanup[3936]: E59146D: message-id=<20221107090811.E59146D@system-name.net.lan>
+                Nov  7 10:08:11 system-name amavis[11]: (00011-01) LMTP::10024 /var/spool/vscan/amavis/tmp/amavis-20221107T100811-00011: <test-sender@system-name.net.lan> -> <test-recipient@system-name.net.lan> SIZE=10888 Received: from system-name.net.lan ([127.0.0.1]) by localhost (system-name.net.lan [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <test-recipient@system-name.net.lan>; Mon,  7 Nov 2022 10:08:11 +0100 (CET)
+                Nov  7 10:08:12 system-name postfix/qmgr[3868]: E59146D: from=<test-sender@system-name.net.lan>, size=9472, nrcpt=1 (queue active)
+                Nov  7 10:08:12 system-name postfix/smtpd[3933]: disconnect from system-name.net.lan[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
+                Nov  7 10:08:12 system-name postfix/smtpd[3933]: connect from system-name.net.lan[127.0.0.1]
+                Nov  7 10:08:12 system-name amavis[11]: (00011-01) Checking: q4eVqFn169Kq [127.0.0.1] <test-sender@system-name.net.lan> -> <test-recipient@system-name.net.lan>
+                Nov  7 10:08:12 system-name amavis[11]: (00011-01) p.path BANNED:1 test-recipient@system-name.net.lan: "P=p003,L=1,M=multipart/mixed | P=p002,L=1/2,M=application/x-msdownload,T=exe,T=exe-ms,N=cloudcar.exe", matching_key="(?^i:\\.exe$)"
+                Nov  7 10:08:12 system-name postfix/qmgr[3868]: 4B0CF70: from=<test-sender@system-name.net.lan>, size=164391, nrcpt=1 (queue active)
+            """
+        lines = [line.lstrip() for line in mail_lines.splitlines() if line.lstrip()]
+        LogFileWriter(self.temp_file, lines, n_writes=len(lines)).start()
+        with open(self.temp_file, 'rt') as file_handle:
+            parser = LogParser(file_handle, SYS_LOG_PATTERN)
+            for _, data, _ in parser:
+                self.assertIsNotNone(data, f"Failed to parse {parser.last_unparsed_line}")
+
     @unittest.skipIf(not os.access('/var/log/messages', os.R_OK),
                      "messages not accessible")
     def test_parse_messages(self):