Merge lp:~free.ekanayaka/landscape-client/release-upgrade-logs into lp:~landscape/landscape-client/trunk

[Free Ekanayaka]

This branch includes the full upgrade-tool logs in the operation result text. Maybe we want also to trim the content of each file if it's too big, like reporting only the *last* N lines. Comments are welcome.

[Sidnei da Silva (sidnei)]

[1] Are we really reading whole files into memory like that? It gives me shivers. We should optimally be generating the message in temporary files and streaming them out on upload if possible, as reading a file of potentially unknown size into memory is a sure way of running into OOM bugs. Failing that, I would go for the 'last N lines' approach right now, instead of waiting until we hit the bug.

review: Needs Fixing

[Jamu Kakar (jkakar)]

[1]

+ def make_operation_result_text(self, out, err):

This method should be using a StringIO internally to avoid copying
strings. This will help with memory use.

[2]

As I recall, Andreas mentioned that the log files are fairly small,
less than 60kb. I think it's probably okay to load them into
memory. That said, as Sidnei suggests, it would be good to put a
safety check in the read_file function and only loads the last N
bytes. N can default to a fairly large number, like 100kb.

review: Needs Fixing

[lp:~free.ekanayaka/landscape-client/release-upgrade-logs]

216. By Free Ekanayaka on 2010-03-16

Read only the last 100kb of the log file and use StringIO (Sidnei [1], Jamu [1] and [2])

[Free Ekanayaka (free.ekanayaka)]

Sidnei, Jamu thanks for the feedback.

The branch now reads only up to the last 100000 bytes of the file, and uses StringIO.

[Jamu Kakar (jkakar)]

Nice work, +1!

review: Approve

[Sidnei da Silva (sidnei)]

Looks good, but you're defaulting to read 100k from the *beginning* of the file (logs_limit is positive)? I think it would be more useful to read from the end of the file. With that change, +1!

review: Approve

[Free Ekanayaka (free.ekanayaka)]

Sidnei, maybe the code is confusing, but it's actually the *end* of the file:

+ content = read_file(filename, - self.logs_limit)

I set logs_limit to a positive value so that it's more user friendly, and the idea is that the fact that internally read_file is used with a negative value should be an implementation detail.

The docstring for logs_limit sounds clear enough to me:

+ @cvar logs_limit: When reporting upgrade-tool logs to the server, only the
+ last C{logs_limit} lines will be sent.

=== modified file 'debian/changelog'
--- debian/changelog	2010-02-09 09:45:00 +0000
+++ debian/changelog	2010-03-16 10:39:30 +0000
@@ -1,3 +1,9 @@
+landscape-client (1.5.0-0ubuntu0.10.04) UNRELEASED; urgency=low
+
+  * New upstream version
+
+ -- Free Ekanayaka <[e-mail]>  Mon, 15 Mar 2010 12:58:44 +0100
+
 landscape-client (1.4.4-0ubuntu0.10.04.0) lucid; urgency=low
 
   * New upstream release (LP: #519200):
 
=== modified file 'landscape/lib/fs.py'
--- landscape/lib/fs.py	2010-02-05 19:12:42 +0000
+++ landscape/lib/fs.py	2010-03-16 10:39:30 +0000
@@ -1,5 +1,7 @@
 """File-system utils"""
 
+import os
+
 
 def create_file(path, content):
     """Create a file with the given content.
@@ -10,3 +12,23 @@
     fd = open(path, "w")
     fd.write(content)
     fd.close()
+
+
+def read_file(path, limit=None):
+    """Return the content of the given file.
+
+    @param path: The path to the file.
+    @param limit: An optional read limit. If positive, read up to that number
+        of bytes from the beginning of the file. If negative, read up to that
+        number of bytes from the end of the file.
+    @return content: The content of the file, possibly trimmed to C{limit}.
+    """
+    fd = open(path, "r")
+    if limit and os.path.getsize(path) > abs(limit):
+        whence = 0
+        if limit < 0:
+            whence = 2
+        fd.seek(limit, whence)
+    content = fd.read()
+    fd.close()
+    return content
 
=== added file 'landscape/lib/tests/test_fs.py'
--- landscape/lib/tests/test_fs.py	1970-01-01 00:00:00 +0000
+++ landscape/lib/tests/test_fs.py	2010-03-16 10:39:30 +0000
@@ -0,0 +1,36 @@
+from landscape.tests.helpers import LandscapeTest
+
+from landscape.lib.fs import read_file
+
+
+class ReadFileTest(LandscapeTest):
+
+    def test_read_file(self):
+        """
+        With no options L{read_file} reads the whole file passed as argument.
+        """
+        path = self.makeFile("foo")
+        self.assertEquals(read_file(path), "foo")
+
+    def test_read_file_with_limit(self):
+        """
+        With a positive limit L{read_file} reads only the bytes after the
+        given limit.
+        """
+        path = self.makeFile("foo bar")
+        self.assertEquals(read_file(path, limit=3), " bar")
+
+    def test_read_file_with_negative_limit(self):
+        """
+        With a negative limit L{read_file} reads only the tail of the file.
+        """
+        path = self.makeFile("foo bar from end")
+        self.assertEquals(read_file(path, limit=-3), "end")
+
+    def test_read_file_with_limit_bigger_than_file(self):
+        """
+        If the limit is bigger than the file L{read_file} reads the entire file.
+        """
+        path = self.makeFile("foo bar from end")
+        self.assertEquals(read_file(path, limit=100), "foo bar from end")
+        self.assertEquals(read_file(path, limit=-100), "foo bar from end")
 
=== modified file 'landscape/package/releaseupgrader.py'
--- landscape/package/releaseupgrader.py	2009-12-15 11:03:31 +0000
+++ landscape/package/releaseupgrader.py	2010-03-16 10:39:30 +0000
@@ -15,6 +15,7 @@
 from landscape.lib.fetch import url_to_filename, fetch_to_files
 from landscape.lib.lsb_release import parse_lsb_release, LSB_RELEASE_FILENAME
 from landscape.lib.gpg import gpg_verify
+from landscape.lib.fs import read_file
 from landscape.package.taskhandler import (
     PackageTaskHandlerConfiguration, PackageTaskHandler, run_task_handler)
 from landscape.manager.manager import SUCCEEDED, FAILED
@@ -33,12 +34,25 @@
 
 
 class ReleaseUpgrader(PackageTaskHandler):
-    """Perform release upgrades."""
+    """Perform release upgrades.
+
+    @cvar config_factory: The configuration class to use to build configuration
+        objects to be passed to our constructor.
+    @cvar queue_name: The queue we pick tasks from.
+    @cvar lsb_release_filename: The path to the LSB data on the file system.
+    @cvar landscape_ppa_url: The URL of the Landscape PPA, if it is present
+        in the computer's sources.list it won't be commented out.
+    @cvar logs_directory: Path to the directory holding the upgrade-tool logs.
+    @cvar logs_limit: When reporting upgrade-tool logs to the server, only the
+        last C{logs_limit} lines will be sent.
+    """
 
     config_factory = ReleaseUpgraderConfiguration
     queue_name = "release-upgrader"
     lsb_release_filename = LSB_RELEASE_FILENAME
     landscape_ppa_url = "http://ppa.launchpad.net/landscape/ppa/ubuntu/"
+    logs_directory = "/var/log/dist-upgrade"
+    logs_limit = 100000
 
     def make_operation_result_message(self, operation_id, status, text, code):
         """Convenience to create messages of type C{"operation-result"}."""
@@ -210,6 +224,28 @@
 
         return succeed(None)
 
+    def make_operation_result_text(self, out, err):
+        """Return the operation result text to be sent to the server.
+
+        @param out: The standard output of the upgrade-tool process.
+        @param err: The standard error of the upgrade-tool process.
+        @return: A text aggregating the process output, error and log files.
+        """
+        buf = cStringIO.StringIO()
+
+        for label, content in [("output", out), ("error", err)]:
+            if content:
+                buf.write("=== Standard %s ===\n\n%s\n\n" % (label, content))
+
+        for basename in os.listdir(self.logs_directory):
+            if not basename.endswith(".log"):
+                continue
+            filename = os.path.join(self.logs_directory, basename)
+            content = read_file(filename, - self.logs_limit)
+            buf.write("=== %s ===\n\n%s\n\n" % (basename, content))
+
+        return buf.getvalue()
+
     def upgrade(self, code_name, operation_id, allow_third_party=False,
                 debug=False, mode=None):
         """Run the upgrade-tool command and send a report of the results.
@@ -267,8 +303,9 @@
                 status = SUCCEEDED
             else:
                 status = FAILED
-            message = self.make_operation_result_message(
-                operation_id, status, "%s%s" % (out, err), code)
+            text = self.make_operation_result_text(out, err)
+            message = self.make_operation_result_message(operation_id, status,
+                                                         text, code)
             logging.info("Queuing message with release upgrade results to "
                          "exchange urgently.")
             return self._broker.send_message(message, True)
 
=== modified file 'landscape/package/tests/test_releaseupgrader.py'
--- landscape/package/tests/test_releaseupgrader.py	2010-01-21 08:47:03 +0000
+++ landscape/package/tests/test_releaseupgrader.py	2010-03-16 10:39:30 +0000
@@ -270,11 +270,93 @@
         result.addCallback(check_result)
         return result
 
+    def test_default_logs_directory(self):
+        """
+        The default directory for the upgrade-tool logs is the system one.
+        """
+        self.assertEquals(self.upgrader.logs_directory,
+                          "/var/log/dist-upgrade")
+
+    def test_default_logs_limit(self):
+        """
+        The default read limit for the upgrade-tool logs is 100000 bytes.
+        """
+        self.assertEquals(self.upgrader.logs_limit, 100000)
+
+    def test_make_operation_result_text(self):
+        """
+        L{ReleaseUpgrade.make_operation_result_text} aggregates the contents of
+        the process standard output, error and log files.
+        """
+        self.upgrader.logs_directory = self.makeDir()
+        self.makeFile(basename="main.log",
+                      dirname=self.upgrader.logs_directory,
+                      content="main log")
+        self.makeFile(basename="apt.log",
+                      dirname=self.upgrader.logs_directory,
+                      content="apt log")
+        text = self.upgrader.make_operation_result_text("stdout", "stderr")
+        self.assertEquals(text,
+                          "=== Standard output ===\n\n"
+                          "stdout\n\n"
+                          "=== Standard error ===\n\n"
+                          "stderr\n\n"
+                          "=== main.log ===\n\n"
+                          "main log\n\n"
+                          "=== apt.log ===\n\n"
+                          "apt log\n\n")
+
+    def test_make_operation_result_text_with_no_stderr(self):
+        """
+        L{ReleaseUpgrade.make_operation_result_text} skips the standard error
+        if it's empty.
+        """
+        self.upgrader.logs_directory = self.makeDir()
+        text = self.upgrader.make_operation_result_text("stdout", "")
+        self.assertEquals(text,
+                          "=== Standard output ===\n\n"
+                          "stdout\n\n")
+
+    def test_make_operation_result_text_only_considers_log_files(self):
+        """
+        L{ReleaseUpgrade.make_operation_result_text} only considers log files
+        from the last upgrade-tool run, directories containing log files from
+        an older run are skipped.
+        """
+        self.upgrader.logs_directory = self.makeDir()
+        self.makeDir(dirname=self.upgrader.logs_directory)
+        text = self.upgrader.make_operation_result_text("stdout", "stderr")
+        self.assertEquals(text,
+                          "=== Standard output ===\n\n"
+                          "stdout\n\n"
+                          "=== Standard error ===\n\n"
+                          "stderr\n\n")
+
+    def test_make_operation_result_text_trims_long_files(self):
+        """
+        L{ReleaseUpgrade.make_operation_result_text} only reads the last
+        L{logs_limit} lines of a log file.
+        """
+        self.upgrader.logs_directory = self.makeDir()
+        self.upgrader.logs_limit = 8
+        self.makeFile(basename="main.log",
+                      dirname=self.upgrader.logs_directory,
+                      content="very long log")
+        text = self.upgrader.make_operation_result_text("stdout", "stderr")
+        self.assertEquals(text,
+                          "=== Standard output ===\n\n"
+                          "stdout\n\n"
+                          "=== Standard error ===\n\n"
+                          "stderr\n\n"
+                          "=== main.log ===\n\n"
+                          "long log\n\n")
+
     def test_upgrade(self):
         """
         The L{ReleaseUpgrader.upgrade} method spawns the appropropriate
         upgrade-tool script and reports the result.
         """
+        self.upgrader.logs_directory = self.makeDir()
         upgrade_tool_directory = self.config.upgrade_tool_directory
         upgrade_tool_filename = os.path.join(upgrade_tool_directory, "karmic")
         fd = open(upgrade_tool_filename, "w")
@@ -298,8 +380,10 @@
                 self.assertIn("INFO: Queuing message with release upgrade "
                               "results to exchange urgently.",
                               self.logfile.getvalue())
-                result_text = u"--frontend DistUpgradeViewNonInteractive\n" \
-                              "FOO=bar\nPWD=%s\nout\n" % upgrade_tool_directory
+                result_text = (u"=== Standard output ===\n\n"
+                               "--frontend DistUpgradeViewNonInteractive\n"
+                               "FOO=bar\n"
+                               "PWD=%s\nout\n\n\n" % upgrade_tool_directory)
                 self.assertMessages(self.get_pending_messages(),
                                     [{"type": "operation-result",
                                       "operation-id": 100,
@@ -324,6 +408,7 @@
         which gets passed to the upgrade-tool script as argument for the
         C{--mode} command line option.
         """
+        self.upgrader.logs_directory = self.makeDir()
         upgrade_tool_directory = self.config.upgrade_tool_directory
         upgrade_tool_filename = os.path.join(upgrade_tool_directory, "hardy")
         self.makeFile(path=upgrade_tool_filename,
@@ -337,8 +422,9 @@
             result = self.upgrader.upgrade("hardy", 100, mode="server")
 
             def check_result(ignored):
-                result_text = ("--frontend DistUpgradeViewNonInteractive "
-                               "--mode server\n")
+                result_text = (u"=== Standard output ===\n\n"
+                               "--frontend DistUpgradeViewNonInteractive "
+                               "--mode server\n\n\n")
                 self.assertMessages(self.get_pending_messages(),
                                     [{"type": "operation-result",
                                       "operation-id": 100,
@@ -357,6 +443,7 @@
         The L{ReleaseUpgrader.upgrade} method optionally sets environment
         variables to be passed to the upgrade-tool process.
         """
+        self.upgrader.logs_directory = self.makeDir()
         upgrade_tool_directory = self.config.upgrade_tool_directory
         upgrade_tool_filename = os.path.join(upgrade_tool_directory, "karmic")
         fd = open(upgrade_tool_filename, "w")
@@ -377,8 +464,9 @@
                                            debug=True)
 
             def check_result(ignored):
-                result_text = u"DEBUG_UPDATE_MANAGER=True\n" \
-                              u"RELEASE_UPRADER_ALLOW_THIRD_PARTY=True\n"
+                result_text = (u"=== Standard output ===\n\n"
+                               "DEBUG_UPDATE_MANAGER=True\n"
+                               "RELEASE_UPRADER_ALLOW_THIRD_PARTY=True\n\n\n")
                 self.assertMessages(self.get_pending_messages(),
                                     [{"type": "operation-result",
                                       "operation-id": 100,
@@ -402,6 +490,7 @@
         The L{ReleaseUpgrader.upgrade} sends a message with failed status
         field if the upgrade-tool exits with non-zero code.
         """
+        self.upgrader.logs_directory = self.makeDir()
         upgrade_tool_directory = self.config.upgrade_tool_directory
         upgrade_tool_filename = os.path.join(upgrade_tool_directory, "karmic")
         fd = open(upgrade_tool_filename, "w")
@@ -419,11 +508,13 @@
             result = self.upgrader.upgrade("karmic", 100)
 
             def check_result(ignored):
+                result_text = (u"=== Standard output ===\n\nout\n\n\n"
+                               "=== Standard error ===\n\nerr\n\n\n")
                 self.assertMessages(self.get_pending_messages(),
                                     [{"type": "operation-result",
                                       "operation-id": 100,
                                       "status": FAILED,
-                                      "result-text": "out\nerr\n",
+                                      "result-text": result_text,
                                       "result-code": 3}])
 
             result.addCallback(check_result)
@@ -439,6 +530,7 @@
         and passes its files descriptors over to child processes we don't know
         about.
         """
+        self.upgrader.logs_directory = self.makeDir()
         upgrade_tool_directory = self.config.upgrade_tool_directory
         upgrade_tool_filename = os.path.join(upgrade_tool_directory, "karmic")
         child_pid_filename = self.makeFile()