Merge lp:~chad.smith/charms/precise/storage/storage-fix-nfs-relation-ordering into lp:~dpb/charms/precise/storage/trunk

[Chad Smith]

Because we cannot rely on ordering of nfs versus data relation hooks fired, we need to account for either the data relation with the principal charm being fired before the nfs relation with the nfs charm or the other way around.

This branch allows either hook to call mount_volume() which will now attempt to grab specific attributes from a designated "data" or "nfs" hook name. This way either hook can determine if all required information is present before proceeding to try mounting the nfs share.

[David Britton (dpb)]

[0] Test failures... Of the form:

https://pastebin.canonical.com/106789/

  File "/usr/lib/python2.7/unittest/case.py", line 331, in run
    testMethod()
  File "/usr/lib/python2.7/dist-packages/mocker.py", line 146, in test_method_wrapper
    result = test_method()
  File "/home/dpb/src/canonical/juju/charms/blockstoragebroker/bsb-ec2-support/hooks/test_util.py", line 1332, in test_wb_ec2_describe_volumes_with_attac
hed_instances
    self.storage._ec2_describe_volumes(), expected)
  File "/home/dpb/src/canonical/juju/charms/blockstoragebroker/bsb-ec2-support/hooks/util.py", line 250, in _ec2_describe_volumes
    command = describevolumes.DescribeVolumes()

[...]

requestbuilder.exceptions.ServiceInitError: No ec2 endpoint to connect to was given. ec2 endpoints may be specified in a config file with "ec2-url".

test_util.TestEC2Util.test_wb_ec2_describe_volumes_with_attached_instances

--
David Britton <email address hidden>

[David Britton (dpb)]

Failure while testing:

2014-03-20 17:02:47 INFO worker.uniter.jujuc server.go:108 running hook tool "relation-set" ["-r" "data:1" "mountpoint=/srv/data"]
2014-03-20 17:02:47 INFO juju.worker.uniter uniter.go:356 ran "block-storage-relation-changed" hook
2014-03-20 17:02:47 INFO juju.worker.uniter uniter.go:363 committing "relation-changed" hook
2014-03-20 17:02:47 INFO juju.worker.uniter uniter.go:381 committed "relation-changed" hook
2014-03-20 17:46:08 INFO juju fslock.go:144 attempted lock failed "uniter-hook-execution", storage/0: running hook "data-relation-departed", currently held: postgresql/0: running hook "data-relation-departed"
2014-03-20 17:46:11 INFO juju fslock.go:144 attempted lock failed "uniter-hook-execution", storage/0: running hook "data-relation-departed", currently held: postgresql/0: running hook "data-relation-broken"
2014-03-20 17:46:13 INFO juju.worker.uniter uniter.go:348 running "data-relation-departed" hook
2014-03-20 17:46:13 INFO worker.uniter.jujuc server.go:108 running hook tool "config-get" ["provider"]
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK Storage provider: block-storage-broker calling data-relation-departed hook
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK umount: /srv/data: device is busy.
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK (In some cases useful info about processes that use
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK the device is found by lsof(8) or fuser(1))
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK Traceback (most recent call last):
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK File "hooks/storage-provider.d/block-storage-broker/data-relation-departed", line 6, in <module>
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK common_util.unmount_volume()
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK File "/var/lib/juju/agents/unit-storage-0/charm/hooks/common_util.py", line 110, in unmount_volume
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK "lsof %s | awk '(NR == 2){print $1}'" % mountpoint)
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK File "/usr/lib/python2.7/subprocess.py", line 537, in check_output
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK process = Popen(stdout=PIPE, *popenargs, **kwargs)
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK File "/usr/lib/python2.7/subprocess.py", line 679, in __init__
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK errread, errwrite)
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK File "/usr/lib/python2.7/subprocess.py", line 1249, in _execute_child
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK raise child_exception
2014-03-20 17:46:13 INFO juju.worker.uniter context.go:255 HOOK OSError: [Errno 2] No such file or directory
2014-03-20 17:46:13 ERROR juju.worker.uniter uniter.go:350 hook failed: exit status 1
2014-03-20 17:46:13 INFO juju.worker.uniter modes.go:421 ModeHookError starting
2014-03-20 17:46:13 INFO juju.worker.uniter.filter f...

[David Britton (dpb)]

[0] can be ignored... wrong MP

[lp:~chad.smith/charms/precise/storage/storage-fix-nfs-relation-ordering]

37. By Chad Smith on 2014-03-20

don't use awk. use python to parse lsof output. Add unit test for lsof subprocess command failure

38. By Chad Smith on 2014-03-20

use lsof -b

[Chad Smith (chad.smith)]

>
> [0] Test failures... Of the form:
>

Okay the above was block-storage-broker charm issues with trusty. Resolved in a followon branch https://code.launchpad.net/~chad.smith/charms/precise/block-storage-broker/bsb-trusty-support

[Chad Smith (chad.smith)]

[1] lsof |awk issues when volume is umounted.... This is resolved by dropping the lsof | awk in subprocess command and instead using subprocess.check_output(["lsof", mountpoint, "-b"])

fixes and unit tests are pushed in rev 37 &38

[Fernando Correa Neto (fcorrea)]

Works great! +1

Went through the process of deploying landscape, nfs and this storage branch.
Tried to establish landscape<->storage and could verify that it didn't go into a error state and it also logged the message.
As soon as I established storage<->nfs, the hooks started firing again and landscape ended with its nfs mounted.

review: Approve

[David Britton (dpb)]

I'm deploying and removing OK now. +1

review: Approve

=== modified file 'hooks/common_util.py'
--- hooks/common_util.py	2014-02-25 23:09:20 +0000
+++ hooks/common_util.py	2014-03-20 21:20:18 +0000
@@ -106,10 +106,15 @@
                 log("Unmounted %s, Done" % mountpoint)
                 break
             else:  # Then device is in use let's report the offending process
-                process_name = subprocess.check_output(
-                    "lsof %s | awk '(NR == 2){print $1}'" % mountpoint)
-                log("WARNING: umount %s failed. Device in use by (%s)" %
-                    (mountpoint, process_name.strip()))
+                message = "WARNING: umount %s failed. Retrying." % mountpoint
+                try:
+                    lsof = subprocess.check_output(["lsof", mountpoint, "-b"])
+                except subprocess.CalledProcessError, e:
+                    log("WARNING: %s" % str(e), hookenv.WARNING)
+                else:
+                    process_name = lsof.split("\n")[1].split()[0]
+                    message += " Device in use by (%s)" % process_name 
+                log(message, hookenv.WARNING)
             sleep(5)
 
     if not success:
@@ -216,17 +221,12 @@
     issue and exit. Otherwise attempt to initialize and mount the blockstorage
     or nfs device.
     """
-    provider = get_provider()
-    if provider == "block-storage-broker":
-        # Called as part of a block storage hook, but mountpoint comes
-        # from the data relation.
-        mountpoint = _get_from_relation("data", "mountpoint")
-    else:
-        mountpoint = hookenv.relation_get("mountpoint")
+    # mountpoint defined by our related principal in the "data" relation
+    mountpoint = _get_from_relation("data", "mountpoint")
 
     if not mountpoint:
         log("No mountpoint defined by relation. Cannot mount volume yet.")
-        sys.exit(0)
+        return
 
     _persist_data("mountpoint", mountpoint)  # Saved for our departed hook
     if is_mounted(mountpoint):
@@ -235,9 +235,10 @@
         for relid in hookenv.relation_ids("data"):
             hookenv.relation_set(
                 relid, relation_settings={"mountpoint": mountpoint})
-        sys.exit(0)
+        return
 
     options = "default"
+    provider = get_provider()
     if provider == "nfs":
         relids = hookenv.relation_ids("nfs")
         for relid in relids:
@@ -250,11 +251,10 @@
                 options = relation.get("options", "default")
                 break
 
-        if None in [nfs_server, nfs_path, fstype]:
-            log("ERROR: Missing required relation values. "
-                "nfs-relation-changed hook needs to run first.",
-                hookenv.ERROR)
-            sys.exit(1)
+        if len(relids) == 0 or None in [nfs_server, nfs_path, fstype]:
+            log("Missing required relation values. "
+                "nfs-relation-changed hook needs to run first.")
+            return
 
         device_path = "%s:%s" % (nfs_server, nfs_path)
     elif provider == "block-storage-broker":

=== modified file 'hooks/storage-provider.d/nfs/data-relation-changed'
--- hooks/storage-provider.d/nfs/data-relation-changed	2014-02-10 18:34:02 +0000
+++ hooks/storage-provider.d/nfs/data-relation-changed	2014-03-20 21:20:18 +0000
@@ -2,4 +2,5 @@
 
 import common_util
 
-common_util.mount_volume()  # Will wait until mountpoint is set by principal
+# Will NOOP until mountpoint is set by principal and relation setup with nfs
+common_util.mount_volume()

=== added symlink 'hooks/storage-provider.d/nfs/nfs-relation-changed'
=== target is u'data-relation-changed'
=== removed file 'hooks/storage-provider.d/nfs/nfs-relation-changed'
--- hooks/storage-provider.d/nfs/nfs-relation-changed	2014-01-31 23:49:37 +0000
+++ hooks/storage-provider.d/nfs/nfs-relation-changed	1970-01-01 00:00:00 +0000
@@ -1,23 +0,0 @@
-#!/usr/bin/python
-
-from charmhelpers.core import hookenv
-import common_util
-import os
-import subprocess
-import sys
-
-current_dir = os.path.dirname(os.path.realpath(__file__))
-config_changed_path = "%s/config-changed" % current_dir
-if os.path.exists(config_changed_path):
-    subprocess.check_call(config_changed_path)
-
-common_util.log("nfs: We've got an nfs mount")
-
-options = hookenv.relation_get("options")
-mountpoint = hookenv.relation_get("mountpoint")
-fstype = hookenv.relation_get("fstype")
-host = hookenv.relation_get("private-address")
-
-if not fstype:
-    common_util.log("nfs: No fstype defined. Waiting for some real data")
-    sys.exit(0)

=== added symlink 'hooks/storage-provider.d/nfs/nfs-relation-departed'
=== target is u'data-relation-departed'
=== removed file 'hooks/storage-provider.d/nfs/nfs-relation-departed'
--- hooks/storage-provider.d/nfs/nfs-relation-departed	2014-01-14 18:53:58 +0000
+++ hooks/storage-provider.d/nfs/nfs-relation-departed	1970-01-01 00:00:00 +0000
@@ -1,7 +0,0 @@
-#!/usr/bin/python
-
-import common_util
-
-common_util.log("nfs: We've lost our shared NFS mount")
-common_util.unmount_volume(remove_persistent_data=True)
-common_util.log("nfs: Fairwell nfs mount, we hardly knew you")

=== modified file 'hooks/test_common_util.py'
--- hooks/test_common_util.py	2014-02-25 23:09:20 +0000
+++ hooks/test_common_util.py	2014-03-20 21:20:18 +0000
@@ -260,6 +260,10 @@
         """
         util._persist_data("mountpoint", "/mnt/this")
 
+        lsof_output = (
+            "COMMAND     PID   USER   FD   TYPE DEVICE SIZE/OFF  NODE NAME\n"
+            "postgresql 30544 csmith   10r   CHR    1,9    0t0  2056 /mnt/this")
+
         ismount = self.mocker.replace(os.path.ismount)
         ismount("/mnt/this")
         self.mocker.result(True)
@@ -268,8 +272,8 @@
         self.mocker.result(2)  # Failure from the shell cmd
         self.mocker.count(20)
         lsof = self.mocker.replace(subprocess.check_output)
-        lsof("lsof /mnt/this | awk '(NR == 2){print $1}'",)
-        self.mocker.result("postgresql")  # Process name using the filesystem
+        lsof(["lsof", "/mnt/this", "-b"])
+        self.mocker.result(lsof_output)
         self.mocker.count(20)
         sleep_mock = self.mocker.replace(sleep)
         sleep_mock(5)
@@ -281,6 +285,36 @@
         self.assertTrue(
             util.hookenv.is_logged(message), "Not logged- %s" % message)
 
+    def test_unmount_lsof_command_failure(self):
+        """Log a warning if lsof fails during L{unmount_volume} retries"""
+        util._persist_data("mountpoint", "/mnt/this")
+
+        ismount = self.mocker.replace(os.path.ismount)
+        ismount("/mnt/this")
+        self.mocker.result(True)
+        umount = self.mocker.replace(subprocess.call)
+        umount(["umount", "/mnt/this"])
+        self.mocker.result(2)  # Failure from the umount shell cmd
+        self.mocker.count(20)
+        lsof = self.mocker.replace(subprocess.check_output)
+        lsof(["lsof", "/mnt/this", "-b"])
+        self.mocker.count(20)
+        self.mocker.throw(
+            subprocess.CalledProcessError(1, "lsof /mnt/this")) # lsof fail
+        sleep_mock = self.mocker.replace(sleep)
+        sleep_mock(5)
+        self.mocker.count(20)
+        self.mocker.replay()
+
+        self.assertRaises(SystemExit, util.unmount_volume)
+        messages = [
+            "ERROR: Unmount failed, leaving relation in errored state",
+            "WARNING: umount /mnt/this failed. Retrying.",
+            "WARNING: Command 'lsof /mnt/this' returned non-zero exit status 1"]
+        for message in messages:
+            self.assertTrue(
+                util.hookenv.is_logged(message), "Not logged- %s" % message)
+
     def test_unmount_volume_success(self):
         """
         L{unmount_volume} will unmount a mounted filesystem calling the shell
@@ -519,8 +553,7 @@
         has not yet defined by the relation principal yet.
         """
         self.assertIsNone(util.hookenv.relation_get("mountpoint"))
-        result = self.assertRaises(SystemExit, util.mount_volume)
-        self.assertEqual(result.code, 0)
+        util.mount_volume()
         message = "No mountpoint defined by relation. Cannot mount volume yet."
         self.assertTrue(
             util.hookenv.is_logged(message), "Not logged- %s" % message)
@@ -533,15 +566,14 @@
         set juju relation C{mountpoint} in response.
         """
         util.hookenv._incoming_relation_data = (
-            (None, "mountpoint", "/mnt/this"),)
+            ("data:1", "mountpoint", "/mnt/this"),)
 
         ismount = self.mocker.replace(os.path.ismount)
         ismount("/mnt/this")
         self.mocker.result(True)
         self.mocker.replay()
 
-        result = self.assertRaises(SystemExit, util.mount_volume)
-        self.assertEqual(result.code, 0)
+        util.mount_volume()
         self.assertIn(("mountpoint", "/mnt/this"),
                       util.hookenv._outgoing_relation_data)
         message = "Volume (/mnt/this) already mounted"
@@ -559,16 +591,16 @@
         already mounted.
         """
         util.hookenv._incoming_relation_data = (
-            (None, "mountpoint", "/mnt/this"),)
-        self.assertEqual(util.hookenv.relation_get("mountpoint"), "/mnt/this")
+            ("data:1", "mountpoint", "/mnt/this"),)
+        self.assertEqual(
+            util.hookenv.relation_get("mountpoint", rid="data:1"), "/mnt/this")
 
         ismount = self.mocker.replace(os.path.ismount)
         ismount("/mnt/this")
         self.mocker.result(True)
         self.mocker.replay()
 
-        result = self.assertRaises(SystemExit, util.mount_volume)
-        self.assertEqual(result.code, 0)
+        util.mount_volume()
         message = "Volume (/mnt/this) already mounted"
         self.assertTrue(
             util.hookenv.is_logged(message), "Not logged- %s" % message)
@@ -581,7 +613,7 @@
         C{mount_type}.
         """
         data = (
-            (None, "mountpoint", "/mnt/this"),
+            ("data:1", "mountpoint", "/mnt/this"),
             ("nfs:1", "private-address", "me.com"),
             ("nfs:1", "mountpoint", "/nfs/server/path"),
             ("nfs:1", "fstype", "nfs"),)
@@ -595,10 +627,11 @@
                     partial_data = partial_data + (item,)
             util.hookenv._incoming_relation_data = partial_data
             self.assertEqual(
-                util.hookenv.relation_get("mountpoint"), "/mnt/this")
-            self.assertRaises(SystemExit, util.mount_volume)
+                util.hookenv.relation_get("mountpoint", rid="data:1"),
+                "/mnt/this")
+            util.mount_volume()
             message = (
-                "ERROR: Missing required relation values. "
+                "Missing required relation values. "
                 "nfs-relation-changed hook needs to run first.")
             self.assertTrue(
                 util.hookenv.is_logged(message), "Not logged- %s" % message)
@@ -614,7 +647,7 @@
         to report the successful initialization to the principal.
         """
         util.hookenv._incoming_relation_data = (
-            (None, "mountpoint", "/mnt/this"),
+            ("data:1", "mountpoint", "/mnt/this"),
             ("nfs:1", "private-address", "me.com"),
             ("nfs:1", "options", "someopts"),
             ("nfs:1", "mountpoint", "/nfs/server/path"),