Merge lp:~veebers/juju-ci-tools/record_timing_actions into lp:juju-ci-tools

[Christopher Lee]

Enable collection of timing data for bootstrap, kill/destroy controller and deploy.

Enable collection of timing data for bootstrap, kill/destroy controller and deploy.

Timing collection for bootstrap and kill/destroy controller are collected without any need for any intervention from a test author.
deploy on the other hand needs to make a change where instead of:
  client.deploy(...)
  client.wait_for_started()
Instead:
  _, deploy_complete = client.deploy(...)
  client.wait_for(deploy_complete)

The resulting timing data looks like: http://paste.ubuntu.com/24265304/

[lp:~veebers/juju-ci-tools/record_timing_actions]

1966. By Christopher Lee on 2017-04-05

Don't actually return non-needed CommandComplete objects.

Unmerged revisions

=== modified file 'assess_container_networking.py'
--- assess_container_networking.py	2017-02-24 18:28:04 +0000
+++ assess_container_networking.py	2017-03-28 03:22:14 +0000
@@ -248,8 +248,9 @@
 
         d = re.search(r'^default\s+via\s+([\d\.]+)\s+', routes, re.MULTILINE)
         if d:
-            rc = client.juju('ssh', ('--proxy', target,
-                                     'ping -c1 -q ' + d.group(1)), check=False)
+            rc, _ = client.juju(
+                'ssh',
+                ('--proxy', target, 'ping -c1 -q ' + d.group(1)), check=False)
             if rc != 0:
                 raise ValueError('%s unable to ping default route' % target)
         else:

=== modified file 'chaos.py'
--- chaos.py	2016-06-27 11:41:04 +0000
+++ chaos.py	2017-03-28 03:22:14 +0000
@@ -146,8 +146,9 @@
         check_cmd += '/chaos_monkey.' + self.monkey_ids[unit_name]
         check_cmd += '/chaos_runner.lock'
         check_cmd += ' ]'
-        if self.client.juju('run', ('--unit', unit_name, check_cmd),
-                            check=False):
+        retvar, _ = self.client.juju(
+            'run', ('--unit', unit_name, check_cmd), check=False)
+        if retvar != 0:
             return 'done'
         return 'running'
 

=== modified file 'deploy_stack.py'
--- deploy_stack.py	2017-03-01 20:34:01 +0000
+++ deploy_stack.py	2017-03-28 03:22:14 +0000
@@ -8,7 +8,6 @@
     from contextlib import nested
 except ImportError:
     from contextlib import ExitStack as nested
-
 import glob
 import logging
 import os
@@ -18,7 +17,7 @@
 import subprocess
 import sys
 import time
-import json
+import yaml
 import shutil
 
 from chaos import background_chaos
@@ -249,10 +248,11 @@
 
 def dump_juju_timings(client, log_directory):
     try:
-        with open(os.path.join(log_directory, 'juju_command_times.json'),
-                  'w') as timing_file:
-            json.dump(client.get_juju_timings(), timing_file, indent=2,
-                      sort_keys=True)
+        report_path = os.path.join(log_directory, 'juju_command_times.yaml')
+        with open(report_path, 'w') as timing_file:
+            yaml.safe_dump(
+                client.get_juju_timings(),
+                timing_file)
             timing_file.write('\n')
     except Exception as e:
         print_now("Failed to save timings")
@@ -534,9 +534,10 @@
 
     def create_initial_model(self, upload_tools, series, boot_kwargs):
         """Create the initial model by bootstrapping."""
-        self.client.bootstrap(
+        _, bootstrap_complete = self.client.bootstrap(
             upload_tools=upload_tools, bootstrap_series=series,
             **boot_kwargs)
+        self.client.get_controller_client().wait_for(bootstrap_complete)
 
     def get_hosts(self):
         """Provide the controller host."""

=== modified file 'jujupy/client.py'
--- jujupy/client.py	2017-03-27 15:15:05 +0000
+++ jujupy/client.py	2017-03-28 03:22:14 +0000
@@ -1095,7 +1095,7 @@
         self.feature_flags = feature_flags
         self.debug = debug
         self._timeout_path = get_timeout_path()
-        self.juju_timings = {}
+        self.juju_timings = []
         self.soft_deadline = soft_deadline
         self._ignore_soft_deadline = False
 
@@ -1131,6 +1131,9 @@
             debug = self.debug
         result = self.__class__(full_path, version, feature_flags, debug,
                                 self.soft_deadline)
+        # Each clone shares a reference to juju_timings allowing us to collect
+        # all commands run during a test.
+        result.juju_timings = self.juju_timings
         return result
 
     @property
@@ -1197,7 +1200,11 @@
     def juju(self, command, args, used_feature_flags,
              juju_home, model=None, check=True, timeout=None, extra_env=None,
              suppress_err=False):
-        """Run a command under juju for the current environment."""
+        """Run a command under juju for the current environment.
+
+        :return: Tuple rval, CommandTime rval being the commands exit code and
+          a CommandTime object used for storing command timing data.
+        """
         args = self.full_args(command, args, model, timeout)
         log.info(' '.join(args))
         env = self.shell_environ(used_feature_flags, juju_home)
@@ -1207,17 +1214,17 @@
             call_func = subprocess.check_call
         else:
             call_func = subprocess.call
-        start_time = time.time()
         # Mutate os.environ instead of supplying env parameter so Windows can
         # search env['PATH']
         stderr = subprocess.PIPE if suppress_err else None
+        # Keep track of commands and how long the take.
+        command_time = CommandTime(command, args, env)
         with scoped_environ(env):
             log.debug('Running juju with env: {}'.format(env))
             with self._check_timeouts():
                 rval = call_func(args, stderr=stderr)
-        self.juju_timings.setdefault(args, []).append(
-            (time.time() - start_time))
-        return rval
+        self.juju_timings.append(command_time)
+        return rval, command_time
 
     def expect(self, command, args, used_feature_flags, juju_home, model=None,
                timeout=None, extra_env=None):
@@ -1296,6 +1303,22 @@
         self.timeout = timeout
         self.already_satisfied = already_satisfied
 
+    def iter_blocking_state(self, status):
+        """Identify when the condition required is met.
+
+        When the operation is complete yield nothing. Otherwise yields a
+        tuple ('<item detail>', '<state>')
+        as to why the action cannot be considered complete yet.
+
+        An example for a condition of an application being removed:
+            yield <application name>, 'still-present'
+        """
+        raise NotImplementedError()
+
+    def do_raise(self, model_name, status):
+        """Raise exception for when success condition fails to be achieved."""
+        raise NotImplementedError()
+
 
 class ConditionList(BaseCondition):
     """A list of conditions that support client.wait_for.
@@ -1325,6 +1348,15 @@
         self._conditions[0].do_raise(model_name, status)
 
 
+class NoopCondition(BaseCondition):
+
+    def iter_blocking_state(self, status):
+        return iter(())
+
+    def do_raise(self, model_name, status):
+        raise Exception('NoopCondition failed: {}'.format(model_name))
+
+
 class WaitMachineNotPresent(BaseCondition):
     """Condition satisfied when a given machine is not present."""
 
@@ -1419,6 +1451,103 @@
         raise VersionsNotUpdated(model_name, status)
 
 
+class WaitAgentsStarted(BaseCondition):
+
+    def __init__(self, timeout=1200):
+        super(WaitAgentsStarted, self).__init__(timeout)
+
+    def iter_blocking_state(self, status):
+        states = Status.check_agents_started(status)
+
+        if states is not None:
+            for state, item in states.items():
+                yield item[0], state
+
+    def do_raise(self, model_name, status):
+        raise AgentsNotStarted(model_name, status)
+
+
+class CommandTime:
+    """Store timing details for a juju command."""
+
+    def __init__(self, cmd, full_args, envvars=None, start=None):
+        """Constructor.
+
+        :param cmd: Command string for command run (e.g. bootstrap)
+        :param args: List of all args the command was called with.
+        :param envvars: Dict of any extra envvars set before command was
+          called.
+        :param start: datetime.datetime object representing when the command
+          was run. If None defaults to datetime.utcnow()
+        """
+        self.cmd = cmd
+        self.full_args = full_args
+        self.envvars = envvars
+        self.start = start if start else datetime.utcnow()
+        self.end = None
+
+    def actual_completion(self, end=None):
+        """Signify that actual completion time of the command.
+
+        Note. ignores multiple calls after the initial call.
+
+        :param end: datetime.datetime object. If None defaults to
+          datetime.datetime.utcnow()
+        """
+        if self.end is None:
+            self.end = end if end else datetime.utcnow()
+
+    @property
+    def total_seconds(self):
+        """Total amount of seconds a command took to complete.
+
+        :return: Int representing number of seconds or None if the command
+          timing has never been completed.
+        """
+        if self.end is None:
+            return None
+        return (self.end - self.start).total_seconds()
+
+
+class CommandComplete(BaseCondition):
+    """Wraps a CommandTime and gives the ability to wait_for completion."""
+
+    def __init__(self, real_condition, command_time):
+        """Constructor.
+
+        :param real_condition: BaseCondition object.
+        :param command_time: CommandTime object representing the command to
+          wait for completion.
+        """
+        super(CommandComplete, self).__init__(
+            real_condition.timeout,
+            real_condition.already_satisfied)
+        self._real_condition = real_condition
+        self.command_time = command_time
+        if real_condition.already_satisfied:
+            self.command_time.actual_completion()
+
+    def iter_blocking_state(self, status):
+        """Wraps the iter_blocking_state of the stored BaseCondition.
+
+        When the operation is complete iter_blocking_state yields nothing.
+        Otherwise iter_blocking_state yields details as to why the action
+        cannot be considered complete yet.
+        """
+        completed = True
+        for item, state in self._real_condition.iter_blocking_state(status):
+            completed = False
+            yield item, state
+        if completed:
+            self.command_time.actual_completion()
+
+    def do_raise(self, status):
+        raise RuntimeError(
+            'Timed out waiting for "{}" command to complete: "{}"'.format(
+                self.command_time.cmd,
+                ' '.join(self.command_time.full_args)))
+
+
 class ModelClient:
     """Wraps calls to a juju instance, associated with a single model.
 
@@ -1833,7 +1962,8 @@
                 upload_tools, config_filename, bootstrap_series, credential,
                 auto_upgrade, metadata_source, no_gui, agent_version)
             self.update_user_name()
-            self.juju('bootstrap', args, include_e=False)
+            retvar, ct = self.juju('bootstrap', args, include_e=False)
+            return retvar, CommandComplete(WaitAgentsStarted(), ct)
 
     @contextmanager
     def bootstrap_async(self, upload_tools=False, bootstrap_series=None,
@@ -1863,7 +1993,7 @@
             '--config', config_file))
 
     def destroy_model(self):
-        exit_status = self.juju(
+        exit_status, _ = self.juju(
             'destroy-model', (self.env.environment, '-y',),
             include_e=False, timeout=get_teardown_timeout(self))
         return exit_status
@@ -1871,22 +2001,32 @@
     def kill_controller(self, check=False):
         """Kill a controller and its models. Hard kill option.
 
-        :return: Subprocess's exit code."""
-        return self.juju(
+        :return: Tuple: Subprocess's exit code, CommandComplete object.
+        """
+        retvar, ct = self.juju(
             'kill-controller', (self.env.controller.name, '-y'),
             include_e=False, check=check, timeout=get_teardown_timeout(self))
+        # Already satisfied as this is a sync, operation.
+        return retvar, CommandComplete(
+            NoopCondition(already_satisfied=True), ct)
 
     def destroy_controller(self, all_models=False):
         """Destroy a controller and its models. Soft kill option.
 
         :param all_models: If true will attempt to destroy all the
             controller's models as well.
-        :raises: subprocess.CalledProcessError if the operation fails."""
+        :raises: subprocess.CalledProcessError if the operation fails.
+        :return: Tuple: Subprocess's exit code, CommandComplete object.
+        """
         args = (self.env.controller.name, '-y')
         if all_models:
             args += ('--destroy-all-models',)
-        return self.juju('destroy-controller', args, include_e=False,
-                         timeout=get_teardown_timeout(self))
+        retvar, ct = self.juju(
+            'destroy-controller', args, include_e=False,
+            timeout=get_teardown_timeout(self))
+        # Already satisfied as this is a sync, operation.
+        return retvar, CommandComplete(
+            NoopCondition(already_satisfied=True), ct)
 
     def tear_down(self):
         """Tear down the client as cleanly as possible.
@@ -1897,7 +2037,7 @@
             self.destroy_controller(all_models=True)
         except subprocess.CalledProcessError:
             logging.warning('tear_down destroy-controller failed')
-            retval = self.kill_controller()
+            retval, _ = self.kill_controller()
             message = 'tear_down kill-controller result={}'.format(retval)
             if retval == 0:
                 logging.info(message)
@@ -1971,7 +2111,8 @@
 
     def set_model_constraints(self, constraints):
         constraint_strings = self._dict_as_option_strings(constraints)
-        return self.juju('set-model-constraints', constraint_strings)
+        retvar, ct = self.juju('set-model-constraints', constraint_strings)
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def get_model_config(self):
         """Return the value of the environment's configured options."""
@@ -1986,11 +2127,13 @@
     def set_env_option(self, option, value):
         """Set the value of the option in the environment."""
         option_value = "%s=%s" % (option, value)
-        return self.juju('model-config', (option_value,))
+        retvar, ct = self.juju('model-config', (option_value,))
+        return CommandComplete(NoopCondition(), ct)
 
     def unset_env_option(self, option):
         """Unset the value of the option in the environment."""
-        return self.juju('model-config', ('--reset', option,))
+        retvar, ct = self.juju('model-config', ('--reset', option,))
+        return CommandComplete(NoopCondition(), ct)
 
     @staticmethod
     def _format_cloud_region(cloud=None, region=None):
@@ -2074,13 +2217,22 @@
 
     def controller_juju(self, command, args):
         args = ('-c', self.env.controller.name) + args
-        return self.juju(command, args, include_e=False)
+        retvar, ct = self.juju(command, args, include_e=False)
+        return CommandComplete(NoopCondition(), ct)
 
     def get_juju_timings(self):
-        stringified_timings = {}
-        for command, timings in self._backend.juju_timings.items():
-            stringified_timings[' '.join(command)] = timings
-        return stringified_timings
+        timing_breakdown = []
+        for ct in self._backend.juju_timings:
+            timing_breakdown.append(
+                {
+                    'command': ct.cmd,
+                    'full_args': ct.full_args,
+                    'start': ct.start,
+                    'end': ct.end,
+                    'total_seconds': ct.total_seconds,
+                }
+            )
+        return timing_breakdown
 
     def juju_async(self, command, args, include_e=True, timeout=None):
         model = self._cmd_model(include_e, controller=False)
@@ -2111,11 +2263,13 @@
             args.extend(['--bind', bind])
         if alias is not None:
             args.extend([alias])
-        return self.juju('deploy', tuple(args))
+        retvar, ct = self.juju('deploy', tuple(args))
+        return retvar, CommandComplete(WaitAgentsStarted(), ct)
 
     def attach(self, service, resource):
         args = (service, resource)
-        return self.juju('attach', args)
+        retvar, ct = self.juju('attach', args)
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def list_resources(self, service_or_unit, details=True):
         args = ('--format', 'yaml', service_or_unit)
@@ -2856,11 +3010,14 @@
         args = ('generate-tools', '-d', source_dir)
         if stream is not None:
             args += ('--stream', stream)
-        return self.juju('metadata', args, include_e=False)
+        retvar, ct = self.juju('metadata', args, include_e=False)
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def add_cloud(self, cloud_name, cloud_file):
-        return self.juju('add-cloud', ("--replace", cloud_name, cloud_file),
-                         include_e=False)
+        retvar, ct = self.juju(
+            'add-cloud', ("--replace", cloud_name, cloud_file),
+            include_e=False)
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def add_cloud_interactive(self, cloud_name, cloud):
         child = self.expect('add-cloud', include_e=False)
@@ -2970,11 +3127,13 @@
 
     def disable_command(self, command_set, message=''):
         """Disable a command-set."""
-        return self.juju('disable-command', (command_set, message))
+        retvar, ct = self.juju('disable-command', (command_set, message))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def enable_command(self, args):
         """Enable a command-set."""
-        return self.juju('enable-command', args)
+        retvar, ct = self.juju('enable-command', args)
+        return CommandComplete(NoopCondition(), ct)
 
     def sync_tools(self, local_dir=None, stream=None, source=None):
         """Copy tools into a local directory or model."""
@@ -2984,10 +3143,12 @@
         if source is not None:
             args += ('--source', source)
         if local_dir is None:
-            return self.juju('sync-tools', args)
+            retvar, ct = self.juju('sync-tools', args)
+            return retvar, CommandComplete(NoopCondition(), ct)
         else:
             args += ('--local-dir', local_dir)
-            return self.juju('sync-tools', args, include_e=False)
+            retvar, ct = self.juju('sync-tools', args, include_e=False)
+            return retvar, CommandComplete(NoopCondition(), ct)
 
     def switch(self, model=None, controller=None):
         """Switch between models."""

=== modified file 'jujupy/fake.py'
--- jujupy/fake.py	2017-03-27 15:15:05 +0000
+++ jujupy/fake.py	2017-03-28 03:22:14 +0000
@@ -35,6 +35,7 @@
     JujuData,
     SoftDeadlineExceeded,
 )
+from jujupy.client import CommandTime
 
 __metaclass__ = type
 
@@ -927,6 +928,7 @@
                 num = int(parsed.n or 1)
                 self.deploy(model_state, parsed.charm_name, num,
                             parsed.service_name, parsed.series)
+                return (0, CommandTime(command, args))
             if command == 'remove-application':
                 model_state.destroy_service(*args)
             if command == 'add-relation':
@@ -975,8 +977,9 @@
                 self.controller_state.destroy()
             if command == 'kill-controller':
                 if self.controller_state.state == 'not-bootstrapped':
-                    return
+                    return (0, CommandTime(command, args))
                 self.controller_state.destroy(kill=True)
+                return (0, CommandTime(command, args))
             if command == 'destroy-model':
                 if not self.is_feature_enabled('jes'):
                     raise JESNotSupported()
@@ -1027,6 +1030,7 @@
                     self.controller_state.shares.remove(username)
             if command == 'restore-backup':
                 model_state.restore_backup()
+            return 0, CommandTime(command, args)
 
     @contextmanager
     def juju_async(self, command, args, used_feature_flags,

=== modified file 'jujupy/tests/test_client.py'
--- jujupy/tests/test_client.py	2017-03-24 23:50:18 +0000
+++ jujupy/tests/test_client.py	2017-03-28 03:22:14 +0000
@@ -43,6 +43,8 @@
     AgentUnresolvedError,
     AppError,
     BaseCondition,
+    CommandTime,
+    CommandComplete,
     CannotConnectEnv,
     ConditionList,
     Controller,
@@ -68,6 +70,7 @@
     make_safe_config,
     ModelClient,
     NameNotAccepted,
+    NoopCondition,
     NoProvider,
     parse_new_state_server_from_error,
     ProvisioningError,
@@ -99,9 +102,11 @@
 from tests import (
     assert_juju_call,
     client_past_deadline,
+    make_fake_juju_return,
     FakeHomeTestCase,
     FakePopen,
     observable_temp_file,
+    patch_juju_call,
     TestCase,
     )
 from jujupy.utility import (
@@ -176,6 +181,12 @@
         self.assertIsNot(cloned, backend)
         self.assertIs(soft_deadline, cloned.soft_deadline)
 
+    def test_cloned_backends_share_juju_timings(self):
+        backend = Juju2Backend('/bin/path', '2.0', set(), False)
+        cloned = backend.clone(
+            full_path=None, version=None, debug=None, feature_flags=None)
+        self.assertIs(cloned.juju_timings, backend.juju_timings)
+
     def test__check_timeouts(self):
         backend = Juju2Backend('/bin/path', '2.0', set(), debug=False,
                                soft_deadline=datetime(2015, 1, 2, 3, 4, 5))
@@ -348,6 +359,21 @@
                          list(conditions.iter_blocking_state(None)))
 
 
+class TestNoopCondition(ClientTest):
+
+    def test_iter_blocking_state_is_noop(self):
+        condition = NoopCondition()
+        called = False
+        for _ in condition.iter_blocking_state({}):
+            called = True
+        self.assertFalse(called)
+
+    def test_do_raise_raises_Exception(self):
+        condition = NoopCondition()
+        with self.assertRaises(Exception):
+            condition.do_raise('model_name', {})
+
+
 class TestWaitMachineNotPresent(ClientTest):
 
     def test_iter_blocking_state(self):
@@ -635,7 +661,7 @@
 
     def test_bootstrap_maas(self):
         env = JujuData('maas', {'type': 'foo', 'region': 'asdf'})
-        with patch.object(ModelClient, 'juju') as mock:
+        with patch_juju_call(ModelClient) as mock:
             client = ModelClient(env, '2.0-zeta1', None)
             with patch.object(client.env, 'maas', lambda: True):
                 with observable_temp_file() as config_file:
@@ -653,7 +679,7 @@
         # Disable space constraint with environment variable
         os.environ['JUJU_CI_SPACELESSNESS'] = "1"
         env = JujuData('maas', {'type': 'foo', 'region': 'asdf'})
-        with patch.object(ModelClient, 'juju') as mock:
+        with patch_juju_call(ModelClient) as mock:
             client = ModelClient(env, '2.0-zeta1', None)
             with patch.object(client.env, 'maas', lambda: True):
                 with observable_temp_file() as config_file:
@@ -669,13 +695,13 @@
     def test_bootstrap_joyent(self):
         env = JujuData('joyent', {
             'type': 'joyent', 'sdc-url': 'https://foo.api.joyentcloud.com'})
-        with patch.object(ModelClient, 'juju', autospec=True) as mock:
-            client = ModelClient(env, '2.0-zeta1', None)
+        client = ModelClient(env, '2.0-zeta1', None)
+        with patch_juju_call(client) as mock:
             with patch.object(client.env, 'joyent', lambda: True):
                 with observable_temp_file() as config_file:
                     client.bootstrap()
             mock.assert_called_once_with(
-                client, 'bootstrap', (
+                'bootstrap', (
                     '--constraints', 'mem=2G cpu-cores=1',
                     'joyent/foo', 'joyent',
                     '--config', config_file.name,
@@ -685,7 +711,7 @@
     def test_bootstrap(self):
         env = JujuData('foo', {'type': 'bar', 'region': 'baz'})
         with observable_temp_file() as config_file:
-            with patch.object(ModelClient, 'juju') as mock:
+            with patch_juju_call(ModelClient) as mock:
                 client = ModelClient(env, '2.0-zeta1', None)
                 client.bootstrap()
                 mock.assert_called_with(
@@ -702,7 +728,7 @@
         env = JujuData('foo', {'type': 'foo', 'region': 'baz'})
         client = ModelClient(env, '2.0-zeta1', None)
         with observable_temp_file() as config_file:
-            with patch.object(client, 'juju') as mock:
+            with patch_juju_call(client) as mock:
                 client.bootstrap(upload_tools=True)
         mock.assert_called_with(
             'bootstrap', (
@@ -715,7 +741,7 @@
         env = JujuData('foo', {'type': 'foo', 'region': 'baz'})
         client = ModelClient(env, '2.0-zeta1', None)
         with observable_temp_file() as config_file:
-            with patch.object(client, 'juju') as mock:
+            with patch_juju_call(client) as mock:
                 client.bootstrap(credential='credential_name')
         mock.assert_called_with(
             'bootstrap', (
@@ -728,7 +754,7 @@
     def test_bootstrap_bootstrap_series(self):
         env = JujuData('foo', {'type': 'bar', 'region': 'baz'})
         client = ModelClient(env, '2.0-zeta1', None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             with observable_temp_file() as config_file:
                 client.bootstrap(bootstrap_series='angsty')
         mock.assert_called_with(
@@ -742,7 +768,7 @@
     def test_bootstrap_auto_upgrade(self):
         env = JujuData('foo', {'type': 'bar', 'region': 'baz'})
         client = ModelClient(env, '2.0-zeta1', None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             with observable_temp_file() as config_file:
                 client.bootstrap(auto_upgrade=True)
         mock.assert_called_with(
@@ -755,7 +781,7 @@
     def test_bootstrap_no_gui(self):
         env = JujuData('foo', {'type': 'bar', 'region': 'baz'})
         client = ModelClient(env, '2.0-zeta1', None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             with observable_temp_file() as config_file:
                 client.bootstrap(no_gui=True)
         mock.assert_called_with(
@@ -768,7 +794,7 @@
     def test_bootstrap_metadata(self):
         env = JujuData('foo', {'type': 'bar', 'region': 'baz'})
         client = ModelClient(env, '2.0-zeta1', None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             with observable_temp_file() as config_file:
                 client.bootstrap(metadata_source='/var/test-source')
         mock.assert_called_with(
@@ -862,7 +888,7 @@
         client = ModelClient(model_data, None, None)
         with patch.object(client, 'get_jes_command',
                           return_value=jes_command):
-                with patch.object(controller_client, 'juju') as ccj_mock:
+                with patch_juju_call(controller_client) as ccj_mock:
                     with observable_temp_file() as config_file:
                         controller_client.add_model(model_data)
         ccj_mock.assert_called_once_with(
@@ -874,7 +900,7 @@
         client.bootstrap()
         client.env.controller.explicit_region = True
         model = client.env.clone('new-model')
-        with patch.object(client._backend, 'juju') as juju_mock:
+        with patch_juju_call(client._backend) as juju_mock:
             with observable_temp_file() as config_file:
                 client.add_model(model)
         juju_mock.assert_called_once_with('add-model', (
@@ -886,7 +912,7 @@
     def test_add_model_by_name(self):
         client = fake_juju_client()
         client.bootstrap()
-        with patch.object(client._backend, 'juju') as juju_mock:
+        with patch_juju_call(client._backend) as juju_mock:
             with observable_temp_file() as config_file:
                 client.add_model('new-model')
         juju_mock.assert_called_once_with('add-model', (
@@ -902,7 +928,7 @@
     def test_destroy_model(self):
         env = JujuData('foo', {'type': 'ec2'})
         client = ModelClient(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.destroy_model()
         mock.assert_called_with(
             'destroy-model', ('foo', '-y'),
@@ -911,7 +937,7 @@
     def test_destroy_model_azure(self):
         env = JujuData('foo', {'type': 'azure'})
         client = ModelClient(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.destroy_model()
         mock.assert_called_with(
             'destroy-model', ('foo', '-y'),
@@ -920,7 +946,7 @@
     def test_destroy_model_gce(self):
         env = JujuData('foo', {'type': 'gce'})
         client = ModelClient(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.destroy_model()
         mock.assert_called_with(
             'destroy-model', ('foo', '-y'),
@@ -928,7 +954,7 @@
 
     def test_kill_controller(self):
         client = ModelClient(JujuData('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.kill_controller()
         juju_mock.assert_called_once_with(
             'kill-controller', ('foo', '-y'), check=False, include_e=False,
@@ -936,7 +962,7 @@
 
     def test_kill_controller_check(self):
         client = ModelClient(JujuData('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.kill_controller(check=True)
         juju_mock.assert_called_once_with(
             'kill-controller', ('foo', '-y'), check=True, include_e=False,
@@ -946,7 +972,7 @@
         client = ModelClient(JujuData('foo', {'type': 'azure'}), None, None)
         with patch.object(client, 'get_jes_command',
                           return_value=jes_command):
-            with patch.object(client, 'juju') as juju_mock:
+            with patch_juju_call(client) as juju_mock:
                 client.kill_controller()
         juju_mock.assert_called_once_with(
             kill_command, ('foo', '-y'), check=False, include_e=False,
@@ -954,7 +980,7 @@
 
     def test_kill_controller_gce(self):
         client = ModelClient(JujuData('foo', {'type': 'gce'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.kill_controller()
         juju_mock.assert_called_once_with(
             'kill-controller', ('foo', '-y'), check=False, include_e=False,
@@ -962,7 +988,7 @@
 
     def test_destroy_controller(self):
         client = ModelClient(JujuData('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.destroy_controller()
         juju_mock.assert_called_once_with(
             'destroy-controller', ('foo', '-y'), include_e=False,
@@ -970,7 +996,7 @@
 
     def test_destroy_controller_all_models(self):
         client = ModelClient(JujuData('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.destroy_controller(all_models=True)
         juju_mock.assert_called_once_with(
             'destroy-controller', ('foo', '-y', '--destroy-all-models'),
@@ -988,7 +1014,9 @@
                                   side_effect=raise_error) as mock:
                     yield mock
             else:
-                with patch.object(target, attribute, autospec=True) as mock:
+                with patch.object(
+                        target, attribute, autospec=True,
+                        return_value=make_fake_juju_return()) as mock:
                     yield mock
 
         with patch_raise(client, 'destroy_controller', destroy_raises
@@ -1219,21 +1247,21 @@
     def test_deploy_non_joyent(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb')
         mock_juju.assert_called_with('deploy', ('mondogb',))
 
     def test_deploy_joyent(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb')
         mock_juju.assert_called_with('deploy', ('mondogb',))
 
     def test_deploy_repository(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('/home/jrandom/repo/mongodb')
         mock_juju.assert_called_with(
             'deploy', ('/home/jrandom/repo/mongodb',))
@@ -1241,7 +1269,7 @@
     def test_deploy_to(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb', to='0')
         mock_juju.assert_called_with(
             'deploy', ('mondogb', '--to', '0'))
@@ -1249,7 +1277,7 @@
     def test_deploy_service(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:mondogb', service='my-mondogb')
         mock_juju.assert_called_with(
             'deploy', ('local:mondogb', 'my-mondogb',))
@@ -1257,14 +1285,14 @@
     def test_deploy_force(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:mondogb', force=True)
         mock_juju.assert_called_with('deploy', ('local:mondogb', '--force',))
 
     def test_deploy_series(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:blah', series='xenial')
         mock_juju.assert_called_with(
             'deploy', ('local:blah', '--series', 'xenial'))
@@ -1272,14 +1300,14 @@
     def test_deploy_multiple(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:blah', num=2)
         mock_juju.assert_called_with(
             'deploy', ('local:blah', '-n', '2'))
 
     def test_deploy_resource(self):
         env = ModelClient(JujuData('foo', {'type': 'local'}), None, None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:blah', resource='foo=/path/dir')
         mock_juju.assert_called_with(
             'deploy', ('local:blah', '--resource', 'foo=/path/dir'))
@@ -1287,7 +1315,7 @@
     def test_deploy_storage(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb', storage='rootfs,1G')
         mock_juju.assert_called_with(
             'deploy', ('mondogb', '--storage', 'rootfs,1G'))
@@ -1295,27 +1323,27 @@
     def test_deploy_constraints(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb', constraints='virt-type=kvm')
         mock_juju.assert_called_with(
             'deploy', ('mondogb', '--constraints', 'virt-type=kvm'))
 
     def test_deploy_bind(self):
         env = ModelClient(JujuData('foo', {'type': 'local'}), None, None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mydb', bind='backspace')
         mock_juju.assert_called_with('deploy', ('mydb', '--bind', 'backspace'))
 
     def test_deploy_aliased(self):
         env = ModelClient(JujuData('foo', {'type': 'local'}), None, None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:blah', alias='blah-blah')
         mock_juju.assert_called_with(
             'deploy', ('local:blah', 'blah-blah'))
 
     def test_attach(self):
         env = ModelClient(JujuData('foo', {'type': 'local'}), None, None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.attach('foo', resource='foo=/path/dir')
         mock_juju.assert_called_with('attach', ('foo', 'foo=/path/dir'))
 
@@ -1383,7 +1411,7 @@
     def test_deploy_bundle_2x(self):
         client = ModelClient(JujuData('an_env', None),
                              '1.23-series-arch', None)
-        with patch.object(client, 'juju') as mock_juju:
+        with patch_juju_call(client) as mock_juju:
             client.deploy_bundle('bundle:~juju-qa/some-bundle')
         mock_juju.assert_called_with(
             'deploy', ('bundle:~juju-qa/some-bundle'), timeout=3600)
@@ -1391,7 +1419,7 @@
     def test_deploy_bundle_template(self):
         client = ModelClient(JujuData('an_env', None),
                              '1.23-series-arch', None)
-        with patch.object(client, 'juju') as mock_juju:
+        with patch_juju_call(client) as mock_juju:
             client.deploy_bundle('bundle:~juju-qa/some-{container}-bundle')
         mock_juju.assert_called_with(
             'deploy', ('bundle:~juju-qa/some-lxd-bundle'), timeout=3600)
@@ -1399,7 +1427,7 @@
     def test_upgrade_charm(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '2.34-74', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.upgrade_charm('foo-service',
                               '/bar/repository/angsty/mongodb')
         mock_juju.assert_called_once_with(
@@ -1409,7 +1437,7 @@
     def test_remove_service(self):
         env = ModelClient(
             JujuData('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.remove_service('mondogb')
         mock_juju.assert_called_with('remove-application', ('mondogb',))
 
@@ -1578,7 +1606,7 @@
 
     def test_remove_machine(self):
         client = fake_juju_client()
-        with patch.object(client._backend, 'juju') as juju_mock:
+        with patch_juju_call(client._backend) as juju_mock:
             condition = client.remove_machine('0')
         call = backend_call(
             client, 'remove-machine', ('0',), 'name:name')
@@ -1587,7 +1615,7 @@
 
     def test_remove_machine_force(self):
         client = fake_juju_client()
-        with patch.object(client._backend, 'juju') as juju_mock:
+        with patch_juju_call(client._backend) as juju_mock:
             client.remove_machine('0', force=True)
         call = backend_call(
             client, 'remove-machine', ('--force', '0'), 'name:name')
@@ -1982,7 +2010,7 @@
 
     def test_list_models(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju') as j_mock:
+        with patch_juju_call(client) as j_mock:
             client.list_models()
         j_mock.assert_called_once_with(
             'list-models', ('-c', 'foo'), include_e=False)
@@ -2194,7 +2222,7 @@
 
     def test_list_controllers(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju') as j_mock:
+        with patch_juju_call(client) as j_mock:
             client.list_controllers()
         j_mock.assert_called_once_with('list-controllers', (), include_e=False)
 
@@ -2662,7 +2690,7 @@
 
     def test_set_model_constraints(self):
         client = ModelClient(JujuData('bar', {}), None, '/foo')
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.set_model_constraints({'bar': 'baz'})
         juju_mock.assert_called_once_with('set-model-constraints',
                                           ('bar=baz',))
@@ -2948,7 +2976,7 @@
     def test_restore_backup(self):
         env = JujuData('qux')
         client = ModelClient(env, None, '/foobar/baz')
-        with patch.object(client, 'juju') as gjo_mock:
+        with patch_juju_call(client) as gjo_mock:
             client.restore_backup('quxx')
         gjo_mock.assert_called_once_with(
             'restore-backup',
@@ -3038,12 +3066,33 @@
         self.assertEqual(0, po_mock.call_count)
 
     def test_get_juju_timings(self):
+        first_start = datetime(2017, 3, 22, 23, 36, 52, 0)
+        first_end = first_start + timedelta(seconds=2)
+        second_start = datetime(2017, 5, 22, 23, 36, 52, 0)
         env = JujuData('foo')
         client = ModelClient(env, None, 'my/juju/bin')
-        client._backend.juju_timings = {("juju", "op1"): [1],
-                                        ("juju", "op2"): [2]}
+        client._backend.juju_timings.extend([
+            CommandTime('command1', ['command1', 'arg1'], start=first_start),
+            CommandTime(
+                'command2', ['command2', 'arg1', 'arg2'], start=second_start)])
+        client._backend.juju_timings[0].actual_completion(end=first_end)
         flattened_timings = client.get_juju_timings()
-        expected = {"juju op1": [1], "juju op2": [2]}
+        expected = [
+            {
+                'command': 'command1',
+                'full_args': ['command1', 'arg1'],
+                'start': first_start,
+                'end': first_end,
+                'total_seconds': 2,
+            },
+            {
+                'command': 'command2',
+                'full_args': ['command2', 'arg1', 'arg2'],
+                'start': second_start,
+                'end': None,
+                'total_seconds': None,
+            }
+        ]
         self.assertEqual(flattened_timings, expected)
 
     def test_deployer(self):
@@ -3230,7 +3279,7 @@
 
     def test_set_config(self):
         client = ModelClient(JujuData('bar', {}), None, '/foo')
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.set_config('foo', {'bar': 'baz'})
         juju_mock.assert_called_once_with('config', ('foo', 'bar=baz'))
 
@@ -3285,7 +3334,7 @@
 
     def test_upgrade_mongo(self):
         client = ModelClient(JujuData('bar', {}), None, '/foo')
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.upgrade_mongo()
         juju_mock.assert_called_once_with('upgrade-mongo', ())
 
@@ -3330,7 +3379,7 @@
         default_model = fake_client.model_name
         default_controller = fake_client.env.controller.name
 
-        with patch.object(fake_client, 'juju', return_value=True):
+        with patch_juju_call(fake_client):
             fake_client.revoke(username)
             fake_client.juju.assert_called_with('revoke',
                                                 ('-c', default_controller,
@@ -3410,7 +3459,7 @@
         env = JujuData('foo')
         username = 'fakeuser'
         client = ModelClient(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.disable_user(username)
         mock.assert_called_with(
             'disable-user', ('-c', 'foo', 'fakeuser'), include_e=False)
@@ -3419,7 +3468,7 @@
         env = JujuData('foo')
         username = 'fakeuser'
         client = ModelClient(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.enable_user(username)
         mock.assert_called_with(
             'enable-user', ('-c', 'foo', 'fakeuser'), include_e=False)
@@ -3427,7 +3476,7 @@
     def test_logout(self):
         env = JujuData('foo')
         client = ModelClient(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.logout()
         mock.assert_called_with(
             'logout', ('-c', 'foo'), include_e=False)
@@ -3678,32 +3727,32 @@
 
     def test_disable_command(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.disable_command('all', 'message')
         mock.assert_called_once_with('disable-command', ('all', 'message'))
 
     def test_enable_command(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.enable_command('all')
         mock.assert_called_once_with('enable-command', 'all')
 
     def test_sync_tools(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.sync_tools()
         mock.assert_called_once_with('sync-tools', ())
 
     def test_sync_tools_local_dir(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.sync_tools('/agents')
         mock.assert_called_once_with('sync-tools', ('--local-dir', '/agents'),
                                      include_e=False)
 
     def test_generate_tool(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.generate_tool('/agents')
         mock.assert_called_once_with('metadata',
                                      ('generate-tools', '-d', '/agents'),
@@ -3711,7 +3760,7 @@
 
     def test_generate_tool_with_stream(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.generate_tool('/agents', "testing")
         mock.assert_called_once_with(
             'metadata', ('generate-tools', '-d', '/agents',
@@ -3719,7 +3768,7 @@
 
     def test_add_cloud(self):
         client = ModelClient(JujuData('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.add_cloud('localhost', 'cfile')
         mock.assert_called_once_with('add-cloud',
                                      ('--replace', 'localhost', 'cfile'),
@@ -3728,7 +3777,7 @@
     def test_switch(self):
         def run_switch_test(expect, model=None, controller=None):
             client = ModelClient(JujuData('foo'), None, None)
-            with patch.object(client, 'juju', autospec=True) as mock:
+            with patch_juju_call(client) as mock:
                 client.switch(model=model, controller=controller)
             mock.assert_called_once_with('switch', (expect,), include_e=False)
         run_switch_test('default', 'default')
@@ -6021,3 +6070,125 @@
         self.assertEqual(host, "2001:db8::3")
         fake_client.status_until.assert_called_once_with(timeout=600)
         self.assertEqual(self.log_stream.getvalue(), "")
+
+
+class TestCommandTime(TestCase):
+
+    def test_default_values(self):
+        full_args = ['juju', '--showlog', 'bootstrap']
+        utcnow = datetime(2017, 3, 22, 23, 36, 52, 530631)
+        with patch('jujupy.client.datetime', autospec=True) as m_dt:
+            m_dt.utcnow.return_value = utcnow
+            ct = CommandTime('bootstrap', full_args)
+            self.assertEqual(ct.cmd, 'bootstrap')
+            self.assertEqual(ct.full_args, full_args)
+            self.assertEqual(ct.envvars, None)
+            self.assertEqual(ct.start, utcnow)
+            self.assertEqual(ct.end, None)
+
+    def test_set_start_time(self):
+        ct = CommandTime('cmd', [], start='abc')
+        self.assertEqual(ct.start, 'abc')
+
+    def test_set_envvar(self):
+        details = {'abc': 123}
+        ct = CommandTime('cmd', [], envvars=details)
+        self.assertEqual(ct.envvars, details)
+
+    def test_actual_completion_sets_default(self):
+        utcnow = datetime(2017, 3, 22, 23, 36, 52, 530631)
+        ct = CommandTime('cmd', [])
+        with patch('jujupy.client.datetime', autospec=True) as m_dt:
+            m_dt.utcnow.return_value = utcnow
+            ct.actual_completion()
+        self.assertEqual(ct.end, utcnow)
+
+    def test_actual_completion_idempotent(self):
+        ct = CommandTime('cmd', [])
+        ct.actual_completion(end='a')
+        ct.actual_completion(end='b')
+        self.assertEqual(ct.end, 'a')
+
+    def test_actual_completion_set_value(self):
+        utcnow = datetime(2017, 3, 22, 23, 36, 52, 530631)
+        ct = CommandTime('cmd', [])
+        ct.actual_completion(end=utcnow)
+        self.assertEqual(ct.end, utcnow)
+
+    def test_total_seconds_returns_None_when_not_complete(self):
+        ct = CommandTime('cmd', [])
+        self.assertEqual(ct.total_seconds, None)
+
+    def test_total_seconds_returns_seconds_taken_to_complete(self):
+        utcstart = datetime(2017, 3, 22, 23, 36, 52, 530631)
+        utcend = utcstart + timedelta(seconds=1)
+        with patch('jujupy.client.datetime', autospec=True) as m_dt:
+            m_dt.utcnow.side_effect = [utcstart, utcend]
+            ct = CommandTime('cmd', [])
+            ct.actual_completion()
+        self.assertEqual(ct.total_seconds, 1)
+
+
+class TestCommandComplete(TestCase):
+
+    def test_default_values(self):
+        ct = CommandTime('cmd', [])
+        base_condition = BaseCondition()
+        cc = CommandComplete(base_condition, ct)
+
+        self.assertEqual(cc.timeout, 300)
+        self.assertEqual(cc.already_satisfied, False)
+        self.assertEqual(cc._real_condition, base_condition)
+        self.assertEqual(cc.command_time, ct)
+        # actual_completion shouldn't be set as the condition is not already
+        # satisfied.
+        self.assertEqual(cc.command_time.end, None)
+
+    def test_sets_total_seconds_when_already_satisfied(self):
+        base_condition = BaseCondition(already_satisfied=True)
+        ct = CommandTime('cmd', [])
+        cc = CommandComplete(base_condition, ct)
+
+        self.assertIsNotNone(cc.command_time.total_seconds)
+
+    def test_calls_wrapper_condition_iter(self):
+        class TestCondition(BaseCondition):
+            def iter_blocking_state(self, status):
+                yield 'item', status
+
+        ct = CommandTime('cmd', [])
+        cc = CommandComplete(TestCondition(), ct)
+
+        k, v = next(cc.iter_blocking_state('status_obj'))
+        self.assertEqual(k, 'item')
+        self.assertEqual(v, 'status_obj')
+
+    def test_sets_actual_completion_when_complete(self):
+        """When the condition hits success must set actual_completion."""
+        class TestCondition(BaseCondition):
+            def __init__(self):
+                super(TestCondition, self).__init__()
+                self._already_called = False
+
+            def iter_blocking_state(self, status):
+                if not self._already_called:
+                    self._already_called = True
+                    yield 'item', status
+
+        ct = CommandTime('cmd', [])
+        cc = CommandComplete(TestCondition(), ct)
+
+        next(cc.iter_blocking_state('status_obj'))
+        self.assertIsNone(cc.command_time.end)
+        next(cc.iter_blocking_state('status_obj'), None)
+        self.assertIsNotNone(cc.command_time.end)
+
+    def test_raises_exception_with_command_details(self):
+        ct = CommandTime('cmd', ['cmd', 'arg1', 'arg2'])
+        cc = CommandComplete(BaseCondition(), ct)
+
+        with self.assertRaises(RuntimeError) as ex:
+            cc.do_raise('status')
+        self.assertEqual(
+            str(ex.exception),
+            'Timed out waiting for "cmd" command to complete: "cmd arg1 arg2"')

=== modified file 'jujupy/tests/test_version_client.py'
--- jujupy/tests/test_version_client.py	2017-03-24 23:50:18 +0000
+++ jujupy/tests/test_version_client.py	2017-03-28 03:22:14 +0000
@@ -69,6 +69,7 @@
     )
 from tests import (
     assert_juju_call,
+    patch_juju_call,
     FakeHomeTestCase,
     FakePopen,
     observable_temp_file,
@@ -367,7 +368,7 @@
     def test_bootstrap(self):
         env = JujuData('foo', {'type': 'bar', 'region': 'baz'})
         with observable_temp_file() as config_file:
-            with patch.object(ModelClientRC, 'juju') as mock:
+            with patch_juju_call(ModelClientRC) as mock:
                 client = ModelClientRC(env, '2.0-zeta1', None)
                 client.bootstrap()
                 mock.assert_called_with(
@@ -432,7 +433,7 @@
     def test_upgrade_juju_nonlocal(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'nonlocal'}), '1.234-76', None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.upgrade_juju()
         juju_mock.assert_called_with(
             'upgrade-juju', ('--version', '1.234'))
@@ -440,7 +441,7 @@
     def test_upgrade_juju_local(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.upgrade_juju()
         juju_mock.assert_called_with(
             'upgrade-juju', ('--version', '1.234', '--upload-tools',))
@@ -448,7 +449,7 @@
     def test_upgrade_juju_no_force_version(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.upgrade_juju(force_version=False)
         juju_mock.assert_called_with(
             'upgrade-juju', ('--upload-tools',))
@@ -467,7 +468,7 @@
 
     def test_bootstrap_maas(self):
         env = SimpleEnvironment('maas')
-        with patch.object(EnvJujuClient1X, 'juju') as mock:
+        with patch_juju_call(EnvJujuClient1X) as mock:
             client = EnvJujuClient1X(env, None, None)
             with patch.object(client.env, 'maas', lambda: True):
                 client.bootstrap()
@@ -475,24 +476,24 @@
 
     def test_bootstrap_joyent(self):
         env = SimpleEnvironment('joyent')
-        with patch.object(EnvJujuClient1X, 'juju', autospec=True) as mock:
+        with patch_juju_call(EnvJujuClient1X) as mock:
             client = EnvJujuClient1X(env, None, None)
             with patch.object(client.env, 'joyent', lambda: True):
                 client.bootstrap()
         mock.assert_called_once_with(
-            client, 'bootstrap', ('--constraints', 'mem=2G cpu-cores=1'))
+                'bootstrap', ('--constraints', 'mem=2G cpu-cores=1'))
 
     def test_bootstrap(self):
         env = SimpleEnvironment('foo')
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.bootstrap()
         mock.assert_called_with('bootstrap', ('--constraints', 'mem=2G'))
 
     def test_bootstrap_upload_tools(self):
         env = SimpleEnvironment('foo')
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.bootstrap(upload_tools=True)
         mock.assert_called_with(
             'bootstrap', ('--upload-tools', '--constraints', 'mem=2G'))
@@ -508,7 +509,7 @@
         env.update_config({
             'default-series': 'angsty',
             })
-        with patch.object(client, 'juju') as mock:
+        with patch_juju_call(client) as mock:
             client.bootstrap(bootstrap_series='angsty')
         mock.assert_called_with('bootstrap', ('--constraints', 'mem=2G'))
 
@@ -573,7 +574,8 @@
     def test_destroy_environment(self):
         env = SimpleEnvironment('foo', {'type': 'ec2'})
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch.object(
+                client, 'juju', autospec=True, return_value=(0, None)) as mock:
             client.destroy_environment()
         mock.assert_called_with(
             'destroy-environment', ('foo', '--force', '-y'),
@@ -582,7 +584,9 @@
     def test_destroy_environment_no_force(self):
         env = SimpleEnvironment('foo', {'type': 'ec2'})
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch.object(
+                client, 'juju',
+                autospec=True, return_value=(0, None)) as mock:
             client.destroy_environment(force=False)
             mock.assert_called_with(
                 'destroy-environment', ('foo', '-y'),
@@ -591,7 +595,8 @@
     def test_destroy_environment_azure(self):
         env = SimpleEnvironment('foo', {'type': 'azure'})
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch.object(
+                client, 'juju', autospec=True, return_value=(0, None)) as mock:
             client.destroy_environment(force=False)
             mock.assert_called_with(
                 'destroy-environment', ('foo', '-y'),
@@ -600,7 +605,9 @@
     def test_destroy_environment_gce(self):
         env = SimpleEnvironment('foo', {'type': 'gce'})
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch.object(
+                client, 'juju',
+                autospec=True, return_value=(0, None)) as mock:
             client.destroy_environment(force=False)
             mock.assert_called_with(
                 'destroy-environment', ('foo', '-y'),
@@ -609,7 +616,8 @@
     def test_destroy_environment_delete_jenv(self):
         env = SimpleEnvironment('foo', {'type': 'ec2'})
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju'):
+        with patch.object(
+                client, 'juju', autospec=True, return_value=(0, None)):
             with temp_env({}) as juju_home:
                 client.env.juju_home = juju_home
                 jenv_path = get_jenv_path(juju_home, 'foo')
@@ -622,7 +630,8 @@
     def test_destroy_model(self):
         env = SimpleEnvironment('foo', {'type': 'ec2'})
         client = EnvJujuClient1X(env, None, None)
-        with patch.object(client, 'juju') as mock:
+        with patch.object(
+                client, 'juju', autospec=True, return_value=(0, None)) as mock:
             client.destroy_model()
         mock.assert_called_with(
             'destroy-environment', ('foo', '-y'),
@@ -631,7 +640,9 @@
     def test_kill_controller(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch.object(
+                client, 'juju',
+                autospec=True, return_value=(0, None)) as juju_mock:
             client.kill_controller()
         juju_mock.assert_called_once_with(
             'destroy-environment', ('foo', '--force', '-y'), check=False,
@@ -640,7 +651,7 @@
     def test_kill_controller_check(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.kill_controller(check=True)
         juju_mock.assert_called_once_with(
             'destroy-environment', ('foo', '--force', '-y'), check=True,
@@ -649,7 +660,7 @@
     def test_destroy_controller(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'ec2'}), None, None)
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.destroy_controller()
         juju_mock.assert_called_once_with(
             'destroy-environment', ('foo', '-y'),
@@ -813,21 +824,21 @@
     def test_deploy_non_joyent(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb')
         mock_juju.assert_called_with('deploy', ('mondogb',))
 
     def test_deploy_joyent(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb')
         mock_juju.assert_called_with('deploy', ('mondogb',))
 
     def test_deploy_repository(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb', '/home/jrandom/repo')
         mock_juju.assert_called_with(
             'deploy', ('mondogb', '--repository', '/home/jrandom/repo'))
@@ -835,7 +846,7 @@
     def test_deploy_to(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('mondogb', to='0')
         mock_juju.assert_called_with(
             'deploy', ('mondogb', '--to', '0'))
@@ -843,7 +854,7 @@
     def test_deploy_service(self):
         env = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(env, 'juju') as mock_juju:
+        with patch_juju_call(env) as mock_juju:
             env.deploy('local:mondogb', service='my-mondogb')
         mock_juju.assert_called_with(
             'deploy', ('local:mondogb', 'my-mondogb',))
@@ -851,7 +862,7 @@
     def test_upgrade_charm(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(client, 'juju') as mock_juju:
+        with patch_juju_call(client) as mock_juju:
             client.upgrade_charm('foo-service',
                                  '/bar/repository/angsty/mongodb')
         mock_juju.assert_called_once_with(
@@ -861,7 +872,7 @@
     def test_remove_service(self):
         client = EnvJujuClient1X(
             SimpleEnvironment('foo', {'type': 'local'}), '1.234-76', None)
-        with patch.object(client, 'juju') as mock_juju:
+        with patch_juju_call(client) as mock_juju:
             client.remove_service('mondogb')
         mock_juju.assert_called_with('destroy-service', ('mondogb',))
 
@@ -1348,7 +1359,7 @@
 
     def test_set_model_constraints(self):
         client = EnvJujuClient1X(SimpleEnvironment('bar', {}), None, '/foo')
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.set_model_constraints({'bar': 'baz'})
         juju_mock.assert_called_once_with('set-constraints', ('bar=baz',))
 
@@ -1592,7 +1603,7 @@
     def test_enable_ha(self):
         env = SimpleEnvironment('qux')
         client = EnvJujuClient1X(env, None, '/foobar/baz')
-        with patch.object(client, 'juju', autospec=True) as eha_mock:
+        with patch_juju_call(client) as eha_mock:
             client.enable_ha()
         eha_mock.assert_called_once_with('ensure-availability', ('-n', '3'))
 
@@ -1657,19 +1668,10 @@
                 client.get_jes_command()
         self.assertEqual(0, po_mock.call_count)
 
-    def test_get_juju_timings(self):
-        env = SimpleEnvironment('foo')
-        client = EnvJujuClient1X(env, None, 'my/juju/bin')
-        client._backend.juju_timings = {("juju", "op1"): [1],
-                                        ("juju", "op2"): [2]}
-        flattened_timings = client.get_juju_timings()
-        expected = {"juju op1": [1], "juju op2": [2]}
-        self.assertEqual(flattened_timings, expected)
-
     def test_deploy_bundle_1x(self):
         client = EnvJujuClient1X(SimpleEnvironment('an_env', None),
                                  '1.23-series-arch', None)
-        with patch.object(client, 'juju') as mock_juju:
+        with patch_juju_call(client) as mock_juju:
             client.deploy_bundle('bundle:~juju-qa/some-bundle')
         mock_juju.assert_called_with(
             'deployer', ('--debug', '--deploy-delay', '10', '--timeout',
@@ -1678,7 +1680,7 @@
     def test_deploy_bundle_template(self):
         client = EnvJujuClient1X(SimpleEnvironment('an_env', None),
                                  '1.23-series-arch', None)
-        with patch.object(client, 'juju') as mock_juju:
+        with patch_juju_call(client) as mock_juju:
             client.deploy_bundle('bundle:~juju-qa/some-{container}-bundle')
         mock_juju.assert_called_with(
             'deployer', (
@@ -1923,14 +1925,14 @@
     def test_add_space(self):
         client = EnvJujuClient1X(SimpleEnvironment(None, {'type': 'local'}),
                                  '1.23-series-arch', None)
-        with patch.object(client, 'juju', autospec=True) as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.add_space('foo-space')
         juju_mock.assert_called_once_with('space create', ('foo-space'))
 
     def test_add_subnet(self):
         client = EnvJujuClient1X(SimpleEnvironment(None, {'type': 'local'}),
                                  '1.23-series-arch', None)
-        with patch.object(client, 'juju', autospec=True) as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.add_subnet('bar-subnet', 'foo-space')
         juju_mock.assert_called_once_with('subnet add',
                                           ('bar-subnet', 'foo-space'))
@@ -1944,7 +1946,7 @@
 
     def test_set_config(self):
         client = EnvJujuClient1X(SimpleEnvironment('bar', {}), None, '/foo')
-        with patch.object(client, 'juju') as juju_mock:
+        with patch_juju_call(client) as juju_mock:
             client.set_config('foo', {'bar': 'baz'})
         juju_mock.assert_called_once_with('set', ('foo', 'bar=baz'))
 
@@ -2065,13 +2067,13 @@
 
     def test_disable_command(self):
         client = EnvJujuClient1X(SimpleEnvironment('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.disable_command('all', 'message')
         mock.assert_called_once_with('block all', ('message', ))
 
     def test_enable_command(self):
         client = EnvJujuClient1X(SimpleEnvironment('foo'), None, None)
-        with patch.object(client, 'juju', autospec=True) as mock:
+        with patch_juju_call(client) as mock:
             client.enable_command('all')
         mock.assert_called_once_with('unblock', 'all')
 

=== modified file 'jujupy/version_client.py'
--- jujupy/version_client.py	2017-03-27 15:15:05 +0000
+++ jujupy/version_client.py	2017-03-28 03:22:14 +0000
@@ -25,6 +25,7 @@
 import yaml
 
 from jujupy.client import (
+    CommandComplete,
     Controller,
     _DEFAULT_BUNDLE_TIMEOUT,
     get_cache_path,
@@ -38,6 +39,7 @@
     LXC_MACHINE,
     make_safe_config,
     ModelClient,
+    NoopCondition,
     SimpleEnvironment,
     Status,
     StatusItem,
@@ -373,7 +375,8 @@
 
     def set_model_constraints(self, constraints):
         constraint_strings = self._dict_as_option_strings(constraints)
-        return self.juju('set-constraints', constraint_strings)
+        retvar, ct = self.juju('set-constraints', constraint_strings)
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def set_config(self, service, options):
         option_strings = ['{}={}'.format(*item) for item in options.items()]
@@ -394,11 +397,13 @@
     def set_env_option(self, option, value):
         """Set the value of the option in the environment."""
         option_value = "%s=%s" % (option, value)
-        return self.juju('set-env', (option_value,))
+        retvar, ct = self.juju('set-env', (option_value,))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def unset_env_option(self, option):
         """Unset the value of the option in the environment."""
-        return self.juju('set-env', ('{}='.format(option),))
+        retvar, ct = self.juju('set-env', ('{}='.format(option),))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def get_model_defaults(self, model_key, cloud=None, region=None):
         log.info('No model-defaults stored for client (attempted get).')
@@ -449,7 +454,8 @@
         """Bootstrap a controller."""
         self._check_bootstrap()
         args = self.get_bootstrap_args(upload_tools, bootstrap_series)
-        self.juju('bootstrap', args)
+        retvar, ct = self.juju('bootstrap', args)
+        return (0, CommandComplete(NoopCondition(), ct))
 
     @contextmanager
     def bootstrap_async(self, upload_tools=False):
@@ -497,25 +503,27 @@
         """Destroy the environment, with force. Hard kill option.
 
         :return: Subprocess's exit code."""
-        return self.juju(
+        retvar, ct = self.juju(
             'destroy-environment', (self.env.environment, '--force', '-y'),
             check=check, include_e=False, timeout=get_teardown_timeout(self))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def destroy_controller(self, all_models=False):
         """Destroy the environment, with force. Soft kill option.
 
         :param all_models: Ignored.
         :raises: subprocess.CalledProcessError if the operation fails."""
-        return self.juju(
+        retvar, ct = self.juju(
             'destroy-environment', (self.env.environment, '-y'),
             include_e=False, timeout=get_teardown_timeout(self))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def destroy_environment(self, force=True, delete_jenv=False):
         if force:
             force_arg = ('--force',)
         else:
             force_arg = ()
-        exit_status = self.juju(
+        exit_status, _ = self.juju(
             'destroy-environment',
             (self.env.environment,) + force_arg + ('-y',),
             check=False, include_e=False,
@@ -572,7 +580,8 @@
             args.extend(['--storage', storage])
         if constraints is not None:
             args.extend(['--constraints', constraints])
-        return self.juju('deploy', tuple(args))
+        retvar, ct = self.juju('deploy', tuple(args))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def upgrade_charm(self, service, charm_path=None):
         args = (service,)
@@ -661,11 +670,13 @@
 
     def disable_command(self, command_set, message=''):
         """Disable a command-set."""
-        return self.juju('block {}'.format(command_set), (message, ))
+        retvar, ct = self.juju('block {}'.format(command_set), (message, ))
+        return retvar, CommandComplete(NoopCondition(), ct)
 
     def enable_command(self, args):
         """Enable a command-set."""
-        return self.juju('unblock', args)
+        retvar, ct = self.juju('unblock', args)
+        return retvar, CommandComplete(NoopCondition(), ct)
 
 
 class EnvJujuClient22(EnvJujuClient1X):

=== modified file 'tests/__init__.py'
--- tests/__init__.py	2017-03-10 19:46:30 +0000
+++ tests/__init__.py	2017-03-28 03:22:14 +0000
@@ -20,6 +20,7 @@
     from unittest.mock import patch
 import yaml
 
+from jujupy.client import CommandTime
 import utility
 
 
@@ -152,12 +153,25 @@
         os.environ[key] = org_value
 
 
+@contextmanager
+def patch_juju_call(client, return_value=0):
+    """Simple patch for client.juju call.
+
+    :param return_value: A tuple to return representing the retvar and
+      CommandTime object
+    """
+    with patch.object(
+            client, 'juju',
+            return_value=make_fake_juju_return(retvar=return_value)) as mock:
+        yield mock
+
+
 def assert_juju_call(test_case, mock_method, client, expected_args,
                      call_index=None):
     """Check a mock's positional arguments.
 
     :param test_case: The test case currently being run.
-    :param mock_mothod: The mock object to be checked.
+    :param mock_method: The mock object to be checked.
     :param client: Ignored.
     :param expected_args: The expected positional arguments for the call.
     :param call_index: Index of the call to check, if None checks first call
@@ -248,3 +262,9 @@
                 },
             }
         }
+
+
+def make_fake_juju_return(
+        retvar=0, cmd='mock_cmd', full_args=[], envvars=None, start=None):
+    """Shadow fake that defaults construction arguments."""
+    return (retvar, CommandTime(cmd, full_args, envvars, start))

=== modified file 'tests/test_assess_block.py'
--- tests/test_assess_block.py	2017-01-20 20:49:41 +0000
+++ tests/test_assess_block.py	2017-03-28 03:22:14 +0000
@@ -18,6 +18,7 @@
     )
 from tests import (
     parse_error,
+    patch_juju_call,
     FakeHomeTestCase,
     TestCase,
     )
@@ -149,7 +150,7 @@
                           autospec=True, side_effect=side_effects):
             with patch('assess_block.deploy_dummy_stack', autospec=True):
                 with patch.object(client, 'remove_service') as mock_rs:
-                    with patch.object(client, 'juju') as mock_juju:
+                    with patch_juju_call(client) as mock_juju:
                         with patch.object(
                                 client, 'wait_for_started') as mock_ws:
                             assess_block(client, 'trusty')

=== modified file 'tests/test_assess_bootstrap.py'
--- tests/test_assess_bootstrap.py	2017-03-01 19:02:24 +0000
+++ tests/test_assess_bootstrap.py	2017-03-28 03:22:14 +0000
@@ -29,6 +29,7 @@
 from tests import (
     FakeHomeTestCase,
     TestCase,
+    make_fake_juju_return,
     )
 from utility import (
     JujuAssertionError,
@@ -361,7 +362,7 @@
         args.temp_env_name = 'qux'
         with extended_bootstrap_cxt('2.0.0'):
             with patch('jujupy.ModelClient.juju', autospec=True,
-                       side_effect=['', '']) as j_mock:
+                       return_value=make_fake_juju_return()) as j_mock:
                 with patch('assess_bootstrap.get_controller_hostname',
                            return_value='test-host', autospec=True):
                     bs_manager = BootstrapManager.from_args(args)

=== modified file 'tests/test_assess_container_networking.py'
--- tests/test_assess_container_networking.py	2017-01-20 20:58:41 +0000
+++ tests/test_assess_container_networking.py	2017-03-28 03:22:14 +0000
@@ -17,6 +17,7 @@
     LXD_MACHINE,
     SimpleEnvironment,
     )
+from jujupy.client import CommandTime
 
 import assess_container_networking as jcnet
 from tests import (
@@ -78,6 +79,29 @@
         if cmd != 'bootstrap':
             self.commands.append((cmd, args))
         if cmd == 'ssh':
+            ct = CommandTime(cmd, args)
+            if len(self._ssh_output) == 0:
+                return "", ct
+
+            try:
+                ct = CommandTime(cmd, args)
+                return self._ssh_output[self._call_number()], ct
+            except IndexError:
+                # If we ran out of values, just return the last one
+                return self._ssh_output[-1], ct
+        else:
+            return super(JujuMock, self).juju(cmd, *rargs, **kwargs)
+
+    def get_juju_output(self, cmd, *rargs, **kwargs):
+        # Almost exactly like juju() except get_juju_output doesn't return
+        # a CommandTime
+        if len(rargs) == 1:
+            args = rargs[0]
+        else:
+            args = rargs
+        if cmd != 'bootstrap':
+            self.commands.append((cmd, args))
+        if cmd == 'ssh':
             if len(self._ssh_output) == 0:
                 return ""
 
@@ -87,7 +111,7 @@
                 # If we ran out of values, just return the last one
                 return self._ssh_output[-1]
         else:
-            return super(JujuMock, self).juju(cmd, *rargs, **kwargs)
+            return super(JujuMock, self).get_juju_output(cmd, *rargs, **kwargs)
 
     def _call_number(self):
         call_number = self._call_n
@@ -117,7 +141,9 @@
             patch.object(self.client, 'wait_for', lambda *args, **kw: None),
             patch.object(self.client, 'wait_for_started',
                          self.juju_mock.get_status),
-            patch.object(self.client, 'get_juju_output', self.juju_mock.juju),
+            patch.object(
+                self.client, 'get_juju_output',
+                self.juju_mock.get_juju_output),
         ]
 
         for patcher in patches:

=== modified file 'tests/test_assess_user_grant_revoke.py'
--- tests/test_assess_user_grant_revoke.py	2017-03-23 19:23:19 +0000
+++ tests/test_assess_user_grant_revoke.py	2017-03-28 03:22:14 +0000
@@ -27,6 +27,7 @@
 from tests import (
     parse_error,
     TestCase,
+    patch_juju_call,
 )
 
 
@@ -150,7 +151,7 @@
     def test_assert_write_model(self):
         fake_client = fake_juju_client()
         with patch.object(fake_client, 'wait_for_started'):
-            with patch.object(fake_client, 'juju', return_value=True):
+            with patch_juju_call(fake_client):
                 assert_write_model(fake_client, 'write', True)
                 with self.assertRaises(JujuAssertionError):
                     assert_write_model(fake_client, 'write', False)

=== modified file 'tests/test_deploy_stack.py'
--- tests/test_deploy_stack.py	2017-03-10 00:50:40 +0000
+++ tests/test_deploy_stack.py	2017-03-28 03:22:14 +0000
@@ -68,6 +68,11 @@
     Status,
     Machine,
     )
+
+from jujupy.client import (
+    NoopCondition,
+    CommandTime,
+)
 from jujupy.configuration import (
     get_environments_path,
     get_jenv_path,
@@ -82,6 +87,7 @@
     assert_juju_call,
     FakeHomeTestCase,
     FakePopen,
+    make_fake_juju_return,
     observable_temp_file,
     temp_os_env,
     use_context,
@@ -221,16 +227,38 @@
         self.assertEqual('region-foo', env.get_region())
 
     def test_dump_juju_timings(self):
+        first_start = datetime(2017, 3, 22, 23, 36, 52, 0)
+        first_end = first_start + timedelta(seconds=2)
+        second_start = datetime(2017, 3, 22, 23, 40, 51, 0)
         env = JujuData('foo', {'type': 'bar'})
         client = ModelClient(env, None, None)
-        client._backend.juju_timings = {("juju", "op1"): [1],
-                                        ("juju", "op2"): [2]}
-        expected = {"juju op1": [1], "juju op2": [2]}
+        client._backend.juju_timings.extend([
+            CommandTime('command1', ['command1', 'arg1'], start=first_start),
+            CommandTime(
+                'command2', ['command2', 'arg1', 'arg2'], start=second_start)
+        ])
+        client._backend.juju_timings[0].actual_completion(end=first_end)
+        expected = [
+            {
+                'command': 'command1',
+                'full_args': ['command1', 'arg1'],
+                'start': first_start,
+                'end': first_end,
+                'total_seconds': 2,
+            },
+            {
+                'command': 'command2',
+                'full_args': ['command2', 'arg1', 'arg2'],
+                'start': second_start,
+                'end': None,
+                'total_seconds': None,
+            }
+        ]
         with temp_dir() as fake_dir:
             dump_juju_timings(client, fake_dir)
             with open(os.path.join(fake_dir,
-                      'juju_command_times.json')) as out_file:
-                file_data = json.load(out_file)
+                      'juju_command_times.yaml')) as out_file:
+                file_data = yaml.load(out_file)
         self.assertEqual(file_data, expected)
 
     def test_check_token(self):
@@ -1757,7 +1785,7 @@
         def do_check(*args, **kwargs):
             with client.check_timeouts():
                 with tear_down_client.check_timeouts():
-                    pass
+                    return make_fake_juju_return()
 
         with patch.object(bs_manager.tear_down_client, 'juju',
                           side_effect=do_check, autospec=True):
@@ -1996,7 +2024,9 @@
         bs_manager.has_controller = False
         with patch('deploy_stack.safe_print_status',
                    autospec=True) as sp_mock:
-            with patch.object(client, 'juju', wrap=client.juju) as juju_mock:
+            with patch.object(
+                    client, 'juju', wrap=client.juju,
+                    return_value=make_fake_juju_return()) as juju_mock:
                 with patch.object(client, 'get_juju_output',
                                   wraps=client.get_juju_output) as gjo_mock:
                     with patch.object(bs_manager, '_should_dump',
@@ -2083,10 +2113,17 @@
     @contextmanager
     def booted_to_bootstrap(self, bs_manager):
         """Preform patches to focus on the call to bootstrap."""
+        # Need basic model details for get_status() (called in wait_for.)
+        bs_manager.client._backend.controller_state.add_model('controller')
+        bootstrap_return = (0, NoopCondition(already_satisfied=True))
         with patch.object(bs_manager, 'dump_all_logs'):
             with patch.object(bs_manager, 'runtime_context'):
-                with patch.object(bs_manager.client, 'juju'):
-                    with patch.object(bs_manager.client, 'bootstrap') as mock:
+                with patch.object(
+                        bs_manager.client, 'juju',
+                        return_value=make_fake_juju_return()):
+                    with patch.object(
+                            bs_manager.client, 'bootstrap',
+                            return_value=bootstrap_return) as mock:
                         yield mock
 
     def test_booted_context_kwargs(self):
@@ -2280,6 +2317,15 @@
             models = [{'name': 'controller'}, {'name': 'bar'}]
         self.addContext(patch.object(client, '_get_models',
                                      return_value=models, autospec=True))
+        # bootstrap now calls wait for.
+        m_controller_client = Mock()
+        m_controller_client.wait_for.return_value = {}
+        self.addContext(
+            patch.object(
+                client,
+                'get_controller_client',
+                autospec=True,
+                return_value=m_controller_client))
         if jes:
             output = jes
         else: