Merge lp:~gary-lasker/software-center/fix-makedirs-race-crashes into lp:software-center

[Gary Lasker]

This branch fixes one of the most common software-center crashes as reported at errors.ubuntu.com, bug 743003, as well as bug 621182. These crashes appear to occur in new installs of Ubuntu, and are the result of a race between different processes creating the cache directory (for bug 743003) and the config directory (for bug 621182). The crash occurs because os.makedirs will throw an OSError if it is called and the directory is found to already exist. The fix for both of these use a new method in utils called safe_makedirs.

I also added a new unit test, test_logging.py, as suggested in comment #3 of bug 743003. This unit test checks the case where the cache directory is found to be not writable, and so is moved aside and a new cache directory created. I'm not sure if the code in log.py itself needs a change as it seems to work fine. It has been modified to use the new safe_makedirs method in any case.

Thanks for your review!

[lp:~gary-lasker/software-center/fix-makedirs-race-crashes]

3007. By Gary Lasker on 2012-05-10

make test_logging.py a little better

[Michael Vogt (mvo)]

Thanks for the branch, it looks good, but there is a issue with the test.

I noticed that you use "os.chmod(cache_dir, 600)" here. As this is decimal 600 (and not octal) its confusing for me to read and will result in a odd permission on disk (see my comment for https://code.launchpad.net/~gary-lasker/software-center/fix-shutdown-crash-lp996333/+merge/105027). Please use either 0400 or stat.S_IRUSR.

It would be nice if safe_makedirs() would get a individual test in test_utils.py (even though its pretty trivial).

[Gary Lasker (gary-lasker)]

Oh sure, thanks, I'll fix that (the value) for both merges. Often, with very trivial details like this, I'll just make the tweak and do the merge, and then just mention the fix here. That way we expedite the merge (reduce the back and forth), and still share knowledge and best practices. I've seen you do that yourself for many merges, so I hope you will feel free to do the same for trivial cases like this.

As far as a test for safe_makedirs, of course my impulse is to write it but I think there comes a point where a test gets to be overkill, and this is one of those cases imo. Meaning, the test itself will probably be 2-3x the lines of code of the function it's actually testing (which is pretty trivial, as you said, really little more than a single line protected by a try/except block). But it's not a problem, I can add it if you really want me to.

[lp:~gary-lasker/software-center/fix-makedirs-race-crashes]

3008. By Gary Lasker on 2012-05-11

use stat values for setting the chmod value in the unit test

[Gary Lasker (gary-lasker)]

Hi Michael, I updated the unit test to use stat.S_IRUSR as this definitely seem more proper (as I mentioned in the other MP). Thanks again!

[Gary Lasker (gary-lasker)]

I took a quick look at making a unit test for safe_makedirs, but I don't immediately see a way to simulate the race condition that causes the error. If you would like a test for that and have any ideas about how to simulate the condition, please let me know and I'll be happy to write the test. As I mentioned, though, I think it's a trivial enough method that a unit test for it is probably overkill.

Thanks again!

[Michael Vogt (mvo)]

Thanks for updating the branch. Its fine now and I merged it into 5.2

I wrote a small unittest that does not exactly simulate the race, but gets close by patching os.path.exists() which will lead to calling the makedir code in any case so we can test that it does not crash for existing dirs and also propergate regular errors still.

As for the earlier comment, I did not want to fix the decimal vs octal issue during the merge because to me its not a trivial detail as it touched the test in such a way that the logic had to be inverted and it also touched two branches.

For small stuff I still do it (and you are always free to correct me here of course when I overdo it or make mistakes).

Small stuff to me is something like:
             LOG.warn("encountered non-writeable file, attempting to fix "
- "by deleting: %s",
- file_path)
+ "by deleting: %s" % file_path)
(not the "," vs the "%s") which is not really as issue as LOG will happily deal with the "," but the "%" is
more python. But no logic changed etc.

[Michael Vogt (mvo)]

I need to correct myself here about my LOG.warn() change. As Natalia pointed out in another branch its actually preferable to use "," in the logging module than to use "%" as it means that on string format mismatches there
will be no expection in the logging. This is a good reason to use "," and we should keep that in mind for
future branches as a good policy.

=== modified file 'softwarecenter/config.py'
--- softwarecenter/config.py	2012-04-02 18:23:20 +0000
+++ softwarecenter/config.py	2012-05-11 22:48:19 +0000
@@ -31,8 +31,8 @@
 
     def __init__(self, config):
         SafeConfigParser.__init__(self)
-        if not os.path.exists(os.path.dirname(config)):
-            os.makedirs(os.path.dirname(config))
+        from utils import safe_makedirs
+        safe_makedirs(os.path.dirname(config))
         # we always want this section, even on fresh installs
         self.add_section("general")
         # read the config

=== modified file 'softwarecenter/log.py'
--- softwarecenter/log.py	2012-03-15 10:43:13 +0000
+++ softwarecenter/log.py	2012-05-11 22:48:19 +0000
@@ -23,6 +23,7 @@
 import os.path
 
 from paths import SOFTWARE_CENTER_CACHE_DIR
+from utils import safe_makedirs
 
 """ setup global logging for software-center """
 
@@ -92,8 +93,7 @@
 handler.addFilter(NullFilterThatWarnsAboutRootLoggerUsage())
 
 # create log file
-if not os.path.exists(SOFTWARE_CENTER_CACHE_DIR):
-    os.makedirs(SOFTWARE_CENTER_CACHE_DIR)
+safe_makedirs(SOFTWARE_CENTER_CACHE_DIR)
 logfile_path = os.path.join(SOFTWARE_CENTER_CACHE_DIR, "software-center.log")
 
 # try to fix inaccessible s-c directory (#688682)
@@ -107,7 +107,7 @@
         if not os.path.exists(target):
             os.rename(SOFTWARE_CENTER_CACHE_DIR, target)
             break
-    os.makedirs(SOFTWARE_CENTER_CACHE_DIR)
+    safe_makedirs(SOFTWARE_CENTER_CACHE_DIR)
 
 # according to bug 688682 many people have a non-writeable logfile
 if os.path.exists(logfile_path) and not os.access(logfile_path, os.W_OK):

=== modified file 'softwarecenter/utils.py'
--- softwarecenter/utils.py	2012-04-25 08:19:42 +0000
+++ softwarecenter/utils.py	2012-05-11 22:48:19 +0000
@@ -28,6 +28,7 @@
 import traceback
 import time
 import xml.sax.saxutils
+import errno
 
 # py3 compat
 try:
@@ -655,6 +656,47 @@
     os.close(lock)
 
 
+def make_string_from_list(base_str, item_list):
+    """ This function takes a list of items and builds a nice human readable
+        string with it of the form. Note that the base string needs a "%s".
+        Example return:
+          The base string with the list items a,b and c in it.
+        Note that base_str needs to be a ngettext string already, so the
+        example usage is:
+         l = ["foo", "bar"]
+         base_str = ngettext("This list: %s.", "This list: %s", len(l))
+         s = make_string_from_list(base_string, l)
+    """
+    list_str = item_list[0]
+    if len(item_list) > 1:
+        # TRANSLATORS: this is a generic list delimit char, e.g. "foo, bar"
+        list_str = _(", ").join(item_list[:-1])
+        # TRANSLATORS: this is the last part of a list, e.g. "foo, bar and baz"
+        list_str = _("%s and %s") % (list_str,
+                                     item_list[-1])
+    s = base_str % list_str
+    return s
+
+
+def safe_makedirs(dir_path):
+    """ This function can be used in place of a straight os.makedirs to
+        handle the possibility of a race condition when more than one
+        process may potentially be creating the same directory (if this occurs,
+        it will throw an OSError, see for example LP: #743003)
+    """
+    if not os.path.exists(dir_path):
+        try:
+            os.makedirs(dir_path)
+        except OSError as e:
+            if e.errno == errno.EEXIST:
+                # it seems that another process has already created this
+                # directory in the meantime, that's ok
+                pass
+            else:
+                # the error is due to something else, so we want to raise it
+                raise
+
+
 class SimpleFileDownloader(GObject.GObject):
 
     LOG = logging.getLogger("softwarecenter.simplefiledownloader")
@@ -782,28 +824,6 @@
         self.emit('file-download-complete', self.dest_file_path)
 
 
-def make_string_from_list(base_str, item_list):
-    """ This function takes a list of items and builds a nice human readable
-        string with it of the form. Note that the base string needs a "%s".
-        Example return:
-          The base string with the list items a,b and c in it.
-        Note that base_str needs to be a ngettext string already, so the
-        example usage is:
-         l = ["foo", "bar"]
-         base_str = ngettext("This list: %s.", "This list: %s", len(l))
-         s = make_string_from_list(base_string, l)
-    """
-    list_str = item_list[0]
-    if len(item_list) > 1:
-        # TRANSLATORS: this is a generic list delimit char, e.g. "foo, bar"
-        list_str = _(", ").join(item_list[:-1])
-        # TRANSLATORS: this is the last part of a list, e.g. "foo, bar and baz"
-        list_str = _("%s and %s") % (list_str,
-                                     item_list[-1])
-    s = base_str % list_str
-    return s
-
-
 # those helpers are packaging system specific
 from softwarecenter.db.pkginfo import get_pkg_info
 # do not call here get_pkg_info, since package switch may not have been set

=== added file 'test/test_logging.py'
--- test/test_logging.py	1970-01-01 00:00:00 +0000
+++ test/test_logging.py	2012-05-11 22:48:19 +0000
@@ -0,0 +1,35 @@
+#!/usr/bin/python
+
+import os
+import stat
+import unittest
+
+from testutils import setup_test_env
+setup_test_env()
+
+
+class TestLogging(unittest.TestCase):
+    """ tests the sc logging facilities """
+
+    def test_no_write_access_for_cache_dir(self):
+        """ test for bug LP: #688682 """
+        # make the test cache dir non-writeable
+        import softwarecenter.paths
+        cache_dir = softwarecenter.paths.SOFTWARE_CENTER_CACHE_DIR
+        os.chmod(cache_dir, stat.S_IRUSR)
+        self.assertFalse(os.access(cache_dir, os.W_OK))
+        # and then start up the logger
+        import softwarecenter.log
+        softwarecenter.log # pyflakes
+        # check that the old directory was moved aside (renamed with a ".0" appended)
+        self.assertTrue(os.path.exists(cache_dir + ".0"))
+        self.assertFalse(os.path.exists(cache_dir + ".1"))
+        # and check that the new directory was created and is now writable
+        self.assertTrue(os.path.exists(cache_dir))
+        self.assertTrue(os.access(cache_dir, os.W_OK))
+
+
+if __name__ == "__main__":
+    import logging
+    logging.basicConfig(level=logging.DEBUG)
+    unittest.main()