Merge lp:~michael.nelson/launchpad/588288-log-parser-dont-read-entire-file-qa into lp:launchpad

[Michael Nelson]

Ensure the next line is incremented when log parser skips lines.

This branch fixes bug 590766 (which was a result of a bad fix landed for bug 588288).

The apache log parser has always ignored lines that are not for an http status 200 OK, or are not GET requests etc. But the current code in devel doesn't increment to the next line when ignoring these lines.

The fix was just a small restructure to ensure that the line is always incremented.

To test:
bin/test -vvm test_apachelogparser

To demo locally:
Apply the following patch so that only 2 lines are read at a time: http://pastebin.ubuntu.com/451153/

Then copy an apache access log from your /var/log/apache2 to /srv/launchpadlibrarian.net-logs

and then run:
cronscripts/parse-librarian-apache-access-logs.py
multiple times. You can watch the data being updated with `psql launchpad_dev` running the query:
select * from parsedapachelog;

No lint.

[Abel Deuring (adeuring)]

Hi Michael,

your changes look good -- but I believe I found another issue in the "while next_line" loop (or I had not have yet enough coffee...):

If we get any exception in the second try/except block of parse_file(), parsed_bytes is set to the value for the start of the line causing the exception, and the loop is terminated via a "break".

So, when parse_file() is called the next time, the line causing the exception is read again. That's fine if the exception of the previous run was due to the line being truncated; in this case, it is fair to assume that a new run with more data will work better. But if the exception is caused for example by a bug in get_method_and_path() or geoip.getRecordByAddress(), we will have an "non-terminating loop", in the sense that sucessive calls of parse_file() will never get past the line causing the exception.

I'm approving this branch but I think it is worth to rethink the exception handling in the loop.

review: Approve (code)

[Abel Deuring (adeuring)]

...one more comment: Can't we use something like

  line[-1] == '\n'

as an indicator if the current line is complete of if we have reached the end of the file and should not parse this line?

[Abel Deuring (adeuring)]

I think that would allow us to remove the "exception Exception" handling

[Michael Nelson (michael.nelson)]

Thanks Abel. Regarding the exception handling, it looks to me as if that is by design (but I didn't design it ;)) - that is, if there is an error the log parser will not continue past the line where the error occurred until it has been resolved (so that we don't end up skipping chunks of the file, but are rather alerted to it). I'm basing this on the test:

    def test_unexpected_error_while_parsing(self):
        # When there's an unexpected error, we log it and return as if we had
        # parsed up to the line before the one where the failure occurred.

I can create a bug with your comments for the foundations guys to look at if you think it's worthwhile.
Thanks!

=== modified file 'lib/canonical/config/schema-lazr.conf'
--- lib/canonical/config/schema-lazr.conf	2010-06-14 18:32:58 +0000
+++ lib/canonical/config/schema-lazr.conf	2010-06-18 11:23:29 +0000
@@ -1132,8 +1132,8 @@
 geonames_identity:
 
 # The maximum number of lines that should be parsed by the launchpad
-# log parser.
-logparser_max_parsed_lines: 100000
+# log parser. The default value of None means there is no maximum.
+logparser_max_parsed_lines: None
 
 
 [launchpad_session]
 
=== modified file 'lib/canonical/launchpad/scripts/tests/test_librarian_apache_log_parser.py'
--- lib/canonical/launchpad/scripts/tests/test_librarian_apache_log_parser.py	2009-12-22 14:08:17 +0000
+++ lib/canonical/launchpad/scripts/tests/test_librarian_apache_log_parser.py	2010-06-18 11:23:29 +0000
@@ -95,10 +95,12 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_library_file_id)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 1 lines resulting in 1 download stats.')
 
         date = datetime(2008, 6, 13)
-        self.assertEqual(downloads, 
+        self.assertEqual(downloads,
             {'15018215': {datetime(2008, 6, 13): {'US': 1}}})
 
         self.assertEqual(parsed_bytes, fd.tell())
@@ -112,7 +114,9 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_library_file_id)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 1 lines resulting in 0 download stats.')
         self.assertEqual(downloads, {})
         self.assertEqual(parsed_bytes, fd.tell())
 
 
=== modified file 'lib/lp/services/apachelogparser/base.py'
--- lib/lp/services/apachelogparser/base.py	2010-06-01 14:31:13 +0000
+++ lib/lp/services/apachelogparser/base.py	2010-06-18 11:23:29 +0000
@@ -85,7 +85,7 @@
     """
     # Seek file to given position, read all lines.
     fd.seek(start_position)
-    line = fd.readline()
+    next_line = fd.readline()
 
     parsed_bytes = start_position
 
@@ -97,16 +97,17 @@
     max_parsed_lines = getattr(
         config.launchpad, 'logparser_max_parsed_lines', None)
 
-    while line:
+    while next_line:
         if max_parsed_lines is not None and parsed_lines >= max_parsed_lines:
             break
 
+        line = next_line
+
         # Always skip the last line as it may be truncated since we're
         # rsyncing live logs, unless there is only one line for us to
         # parse, in which case This probably means we're dealing with a
         # logfile that has been rotated already, so it should be safe to
         # parse its last line.
-        next_line = ''
         try:
             next_line = fd.next()
         except StopIteration:
@@ -161,7 +162,11 @@
             logger.error('Error (%s) while parsing "%s"' % (e, line))
             break
 
-        line = next_line
+
+    if parsed_lines > 0:
+        logger.info('Parsed %d lines resulting in %d download stats.' % (
+            parsed_lines, len(downloads)))
+
     return downloads, parsed_bytes
 
 
 
=== modified file 'lib/lp/services/apachelogparser/tests/apache-log-files/launchpadlibrarian.net.access-log'
--- lib/lp/services/apachelogparser/tests/apache-log-files/launchpadlibrarian.net.access-log	2009-03-27 03:29:31 +0000
+++ lib/lp/services/apachelogparser/tests/apache-log-files/launchpadlibrarian.net.access-log	2010-06-18 11:23:29 +0000
@@ -1,3 +1,4 @@
+121.44.28.210 - - [13/Jun/2008:14:55:06 +0100] "GET /9096290/me-tv-icon-14x14.png HTTP/1.1" 404 730 "https://launchpad.net/me-tv" "Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9) Gecko/2008060900 Firefox/3.0"
 121.44.28.210 - - [13/Jun/2008:14:55:06 +0100] "GET /9096290/me-tv-icon-14x14.png HTTP/1.1" 200 730 "https://launchpad.net/me-tv" "Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9) Gecko/2008060900 Firefox/3.0"
 121.44.28.210 - - [13/Jun/2008:14:55:13 +0100] "GET /12060796/me-tv-icon-64x64.png HTTP/1.1" 200 6378 "https://launchpad.net/me-tv" "Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9) Gecko/2008060900 Firefox/3.0"
 157.92.18.21 - - [13/Jun/2008:14:55:15 +0100] "GET /8196569/mediumubuntulogo.png HTTP/1.1" 200 3420 "https://bugs.launchpad.net/ubuntu/+source/acpi-support/+bug/59695/comments/14" "Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9) Gecko/2008052623 Iceweasel/3.0 (Debian-3.0~rc1-1)"
 
=== modified file 'lib/lp/services/apachelogparser/tests/test_apachelogparser.py'
--- lib/lp/services/apachelogparser/tests/test_apachelogparser.py	2010-06-01 14:28:40 +0000
+++ lib/lp/services/apachelogparser/tests/test_apachelogparser.py	2010-06-18 11:23:29 +0000
@@ -126,7 +126,9 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_path_download_key)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 5 lines resulting in 3 download stats.')
         date = datetime(2008, 6, 13)
         self.assertContentEqual(
             downloads.items(),
@@ -148,7 +150,9 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=self._getLastLineStart(fd), logger=self.logger,
             get_download_key=get_path_download_key)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 1 lines resulting in 1 download stats.')
         self.assertEqual(parsed_bytes, fd.tell())
 
         self.assertContentEqual(
@@ -175,7 +179,9 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_path_download_key)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 1 lines resulting in 0 download stats.')
         self.assertEqual(downloads, {})
         self.assertEqual(parsed_bytes, fd.tell())
 
@@ -198,7 +204,9 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_path_download_key)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 1 lines resulting in 0 download stats.')
         self.assertEqual(downloads, {})
         self.assertEqual(parsed_bytes, fd.tell())
 
@@ -214,9 +222,10 @@
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_path_download_key)
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        self.assertEqual(
+            self.logger.buffer.getvalue().strip(),
+            'INFO: Parsed 1 lines resulting in 1 download stats.')
 
-        date = datetime(2008, 6, 13)
         self.assertEqual(downloads,
             {'/15018215/ul_logo_64x64.png':
                 {datetime(2008, 6, 13): {'US': 1}}})
@@ -232,24 +241,37 @@
                 [launchpad]
                 logparser_max_parsed_lines: 2
                 '''))
+        self.addCleanup(config.pop, 'log_parser config')
         fd = open(os.path.join(
             here, 'apache-log-files', 'launchpadlibrarian.net.access-log'))
+        self.addCleanup(fd.close)
+
         downloads, parsed_bytes = parse_file(
             fd, start_position=0, logger=self.logger,
             get_download_key=get_path_download_key)
-        config.pop("log_parser config")
 
-        self.assertEqual(self.logger.buffer.getvalue(), '')
+        # We have initially parsed only the first two lines of data,
+        # corresponding to one download (the first line is a 404 and
+        # so ignored).
         date = datetime(2008, 6, 13)
         self.assertContentEqual(
             downloads.items(),
-            [('/12060796/me-tv-icon-64x64.png', {date: {'AU': 1}}),
-             ('/9096290/me-tv-icon-14x14.png', {date: {'AU': 1}})])
-
-        # We should have parsed only the first two lines of data.
+            [('/9096290/me-tv-icon-14x14.png', {date: {'AU': 1}})])
         fd.seek(0)
         lines = fd.readlines()
-        self.assertEqual(parsed_bytes, len(lines[0]) + len(lines[1]))
+        line_lengths = [len(line) for line in lines]
+        self.assertEqual(parsed_bytes, sum(line_lengths[:2]))
+
+        # And the subsequent parse will be for the 3rd and 4th lines,
+        # corresponding to two downloads of the same file.
+        downloads, parsed_bytes = parse_file(
+            fd, start_position=parsed_bytes, logger=self.logger,
+            get_download_key=get_path_download_key)
+        self.assertContentEqual(
+            downloads.items(),
+            [('/12060796/me-tv-icon-64x64.png', {date: {'AU': 1}}),
+             ('/8196569/mediumubuntulogo.png', {date: {'AR': 1}})])
+        self.assertEqual(parsed_bytes, sum(line_lengths[:4]))
 
 
 class TestParsedFilesDetection(TestCase):