Progress Reporting for long running operations

requirements.txt

@@ -2,6 +2,7 @@ adal==0.4.3
 applicationinsights==0.10.0
 argcomplete==1.8.0
 colorama==0.3.7
+humanfriendly==2.4
 jmespath
 mock==1.3.0
 paramiko==2.0.2

scripts/automation/tests/verify_dependencies.py

@@ -11,7 +11,7 @@
 import sys
 
 ALLOWED_ERRORS = [
-    "has requirement azure-common[autorest]==1.1.4, but you have azure-common 1.1.5.",
+    "has requirement azure-common[autorest]==1.1.4, but you have azure-common 1.1.6.",
     "has requirement azure-common~=1.1.5, but you have azure-common 1.1.4."
 ]
 

src/azure-cli-core/azure/cli/core/application.py

@@ -15,6 +15,7 @@
 import azure.cli.core.azlogging as azlogging
 from azure.cli.core.util import todict, truncate_text, CLIError, read_file_content
 from azure.cli.core._config import az_config
+import azure.cli.core.commands.progress as progress
 
 import azure.cli.core.telemetry as telemetry
 
@@ -127,6 +128,11 @@ def __init__(self, configuration=None):
 
         self.parser = AzCliCommandParser(prog='az', parents=[self.global_parser])
         self.configuration = configuration
+        self.progress_controller = progress.ProgressHook()
+
+    def get_progress_controller(self):
+        self.progress_controller.init_progress(progress.get_progress_view())
+        return self.progress_controller
 
     def initialize(self, configuration):
         self.configuration = configuration

src/azure-cli-core/azure/cli/core/commands/__init__.py

@@ -21,7 +21,6 @@
 import azure.cli.core.azlogging as azlogging
 import azure.cli.core.telemetry as telemetry
 from azure.cli.core.util import CLIError
-from azure.cli.core.application import APPLICATION
 from azure.cli.core.prompting import prompt_y_n, NoTTYException
 from azure.cli.core._config import az_config, DEFAULTS_SECTION
 from azure.cli.core.profiles import ResourceType, supported_api_version
@@ -126,10 +125,13 @@ def __setattr__(self, name, value):
 
 class LongRunningOperation(object):  # pylint: disable=too-few-public-methods
 
-    def __init__(self, start_msg='', finish_msg='', poller_done_interval_ms=1000.0):
+    def __init__(self, start_msg='', finish_msg='',
+                 poller_done_interval_ms=1000.0, progress_controller=None):
         self.start_msg = start_msg
         self.finish_msg = finish_msg
         self.poller_done_interval_ms = poller_done_interval_ms
+        from azure.cli.core.application import APPLICATION
+        self.progress_controller = progress_controller or APPLICATION.get_progress_controller()
 
     def _delay(self):
         time.sleep(self.poller_done_interval_ms / 1000.0)
@@ -138,7 +140,9 @@ def __call__(self, poller):
         from msrest.exceptions import ClientException
         logger.info("Starting long running operation '%s'", self.start_msg)
         correlation_message = ''
+        self.progress_controller.begin()
         while not poller.done():
+            self.progress_controller.add(message='Running')
             try:
                 # pylint: disable=protected-access
                 correlation_id = json.loads(
@@ -151,8 +155,10 @@ def __call__(self, poller):
             try:
                 self._delay()
             except KeyboardInterrupt:
+                self.progress_controller.stop()
                 logger.error('Long running operation wait cancelled.  %s', correlation_message)
                 raise
+
         try:
             result = poller.result()
         except ClientException as client_exception:
@@ -161,6 +167,7 @@ def __call__(self, poller):
                 fault_type='failed-long-running-operation',
                 summary='Unexpected client exception in {}.'.format(LongRunningOperation.__name__))
             message = getattr(client_exception, 'message', client_exception)
+            self.progress_controller.stop()
 
             try:
                 message = '{} {}'.format(
@@ -176,6 +183,7 @@ def __call__(self, poller):
 
         logger.info("Long running operation '%s' completed with result %s",
                     self.start_msg, result)
+        self.progress_controller.end()
         return result
 
 
@@ -232,6 +240,8 @@ def __init__(self, name, handler, description=None, table_transformer=None,
 
     @staticmethod
     def _should_load_description():
+        from azure.cli.core.application import APPLICATION
+
         return not APPLICATION.session['completer_active']
 
     def load_arguments(self):

src/azure-cli-core/azure/cli/core/commands/progress.py

@@ -0,0 +1,165 @@
+# --------------------------------------------------------------------------------------------
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License. See License.txt in the project root for license information.
+# --------------------------------------------------------------------------------------------
+from __future__ import division
+import sys
+import platform
+
+import humanfriendly
+BAR_LEN = 70
+
+if platform.system() == 'Windows':
+    humanfriendly.erase_line_code = ''
+
+
+class ProgressViewBase(object):
+    """ a view base for progress reporting """
+    def __init__(self, out):
+        self.out = out
+
+    def write(self, args):
+        """ writes the progress """
+        raise NotImplementedError
+
+    def flush(self):
+        """ flushes the message out the pipeline"""
+        raise NotImplementedError
+
+    def clear(self):
+        """ resets the view to neutral """
+        pass
+
+
+class ProgressReporter(object):
+    """ generic progress reporter """
+    def __init__(self, message='', value=None, total_value=None):
+        self.message = message
+        self.value = value
+        self.total_val = total_value
+        self.closed = False
+
+    def add(self, **kwargs):
+        """
+        adds a progress report
+        :param kwargs: dictionary containing 'message', 'total_val', 'value'
+        """
+        message = kwargs.get('message', self.message)
+        total_val = kwargs.get('total_val', self.total_val)
+        value = kwargs.get('value', self.value)
+        if value and total_val:
+            assert value >= 0 and value <= total_val and total_val >= 0
+            self.closed = value == total_val
+        self.total_val = total_val
+        self.value = value
+        self.message = message
+
+    def report(self):
+        """ report the progress """
+        percent = self.value / self.total_val if self.value is not None and self.total_val else None
+        return {'message': self.message, 'percent': percent}
+
+
+class ProgressHook(object):
+    """ sends the progress to the view """
+    def __init__(self):
+        self.reporter = ProgressReporter()
+        self.active_progress = None
+
+    def init_progress(self, progress_view):
+        """ activate a view """
+        self.active_progress = progress_view
+
+    def add(self, **kwargs):
+        """ adds a progress report """
+        self.reporter.add(**kwargs)
+        self.update()
+
+    def update(self):
+        """ updates the view with the progress """
+        self.active_progress.write(self.reporter.report())
+        self.active_progress.flush()
+
+    def stop(self):
+        """ if there is an abupt stop before ending """
+        self.reporter.closed = True
+        self.add(message='Interrupted')
+        self.active_progress.clear()
+
+    def begin(self, **kwargs):
+        """ start reporting progress """
+        kwargs['message'] = kwargs.get('message', 'Starting')
+        self.add(**kwargs)
+
+    def end(self, **kwargs):
+        """ ending reporting of progress """
+        kwargs['message'] = kwargs.get('message', 'Finished')
+        self.reporter.closed = True
+        self.add(**kwargs)
+        self.active_progress.clear()
+
+    def is_running(self):
+        """ whether progress is continuing """
+        return not self.reporter.closed
+
+
+class IndeterminateStandardOut(ProgressViewBase):
+    """ custom output for progress reporting """
+    def __init__(self, out=None):
+        super(IndeterminateStandardOut, self).__init__(
+            out if out else sys.stderr)
+        self.spinner = None
+
+    def write(self, args):
+        """
+        writes the progress
+        :param args: dictionary containing key 'message'
+        """
+        if self.spinner is None:
+            self.spinner = humanfriendly.Spinner(
+                label='In Progress', stream=self.out, hide_cursor=False)
+        msg = args.get('message', 'In Progress')
+        self.spinner.step(label=msg)
+
+    def flush(self):
+        self.out.flush()
+
+
+def _format_value(msg, percent):
+    bar_len = BAR_LEN - len(msg) - 1
+    completed = int(bar_len * percent)
+
+    message = '\r{}['.format(msg)
+    message += ('#' * completed).ljust(bar_len)
+    message += ']  {:.4%}'.format(percent)
+    return message
+
+
+class DeterminateStandardOut(ProgressViewBase):
+    """ custom output for progress reporting """
+    def __init__(self, out=None):
+        super(DeterminateStandardOut, self).__init__(out if out else sys.stderr)
+
+    def write(self, args):
+        """
+        writes the progress
+        :param args: args is a dictionary containing 'percent', 'message'
+        """
+        percent = args.get('percent', 0)
+        message = args.get('message', '')
+
+        if percent:
+            percent = percent
+            progress = _format_value(message, percent)
+            self.out.write(progress)
+
+    def flush(self):
+        pass
+
+
+def get_progress_view(determinant=False, outstream=sys.stderr):
+    """ gets your view """
+    if determinant:
+        return DeterminateStandardOut(out=outstream)
+    else:
+        return IndeterminateStandardOut(out=outstream)

src/azure-cli-core/azure/cli/core/parser.py

@@ -161,7 +161,6 @@ def validation_error(self, message):
     def error(self, message):
         telemetry.set_user_fault('parse error: {}'.format(message))
         self._handle_command_package_error(message)
-
         args = {'prog': self.prog, 'message': message}
         logger.error('%(prog)s: error: %(message)s', args)
         self.print_usage(sys.stderr)

src/azure-cli-core/setup.py

@@ -55,6 +55,7 @@
     'applicationinsights',
     'argcomplete>=1.8.0',
     'colorama',
+    'humanfriendly',
     'jmespath',
     'msrest>=0.4.4',
     'msrestazure>=0.4.7',

src/azure-cli-core/tests/test_progress.py

@@ -0,0 +1,100 @@
+# --------------------------------------------------------------------------------------------
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License. See License.txt in the project root for license information.
+# --------------------------------------------------------------------------------------------
+import unittest
+
+import azure.cli.core.commands.progress as progress
+
+
+class MockOutstream(progress.ProgressViewBase):
+    """ mock outstream for testing """
+    def __init__(self):
+        self.string = ''
+
+    def write(self, message):
+        self.string = message
+
+    def flush(self):
+        pass
+
+
+class TestProgress(unittest.TestCase):  # pylint: disable=too-many-public-methods
+    """ test the progress reporting """
+
+    def test_progress_indicator_det_model(self):
+        """ test the progress reporter """
+        reporter = progress.ProgressReporter()
+        args = reporter.report()
+        self.assertEqual(args['message'], '')
+        self.assertEqual(args['percent'], None)
+
+        reporter.add(message='Progress', total_val=10, value=0)
+        self.assertEqual(reporter.message, 'Progress')
+        self.assertEqual(reporter.value, 0)
+        self.assertEqual(reporter.total_val, 10)
+        args = reporter.report()
+        self.assertEqual(args['message'], 'Progress')
+        self.assertEqual(args['percent'], 0)
+
+        with self.assertRaises(AssertionError):
+            reporter.add(message='In words', total_val=-1, value=10)
+        with self.assertRaises(AssertionError):
+            reporter.add(message='In words', total_val=1, value=-10)
+        with self.assertRaises(AssertionError):
+            reporter.add(message='In words', total_val=30, value=12340)
+
+        reporter = progress.ProgressReporter()
+        message = reporter.report()
+        self.assertEqual(message['message'], '')
+
+        reporter.add(message='Progress')
+        self.assertEqual(reporter.message, 'Progress')
+
+        message = reporter.report()
+        self.assertEqual(message['message'], 'Progress')
+
+    def test_progress_indicator_indet_stdview(self):
+        """ tests the indeterminate progress standardout view """
+        outstream = MockOutstream()
+        view = progress.IndeterminateStandardOut(out=outstream)
+        view.write({})
+        self.assertEqual(view.spinner.label, 'In Progress')
+        before = view.spinner.total
+        view.write({})
+        after = view.spinner.total
+        self.assertTrue(after >= before)
+        view.write({'message': 'TESTING'})
+
+    def test_progress_indicator_det_stdview(self):
+        """ test the determinate progress standardout view """
+        outstream = MockOutstream()
+        view = progress.DeterminateStandardOut(out=outstream)
+        view.write({'message': 'hihi', 'percent': .5})
+        # 95 length, 48 complete, 4 dec percent
+        bar_str = ('#' * int(.5 * 65)).ljust(65)
+        self.assertEqual(outstream.string, '\rhihi[{}]  {:.4%}'.format(bar_str, .5))
+
+        view.write({'message': '', 'percent': .9})
+        # 99 length, 90 complete, 4 dec percent
+        bar_str = ('#' * int(.9 * 69)).ljust(69)
+        self.assertEqual(outstream.string, '\r[{}]  {:.4%}'.format(bar_str, .9))
+
+    def test_progress_indicator_controller(self):
+        """ tests the controller for progress reporting """
+        controller = progress.ProgressHook()
+        view = MockOutstream()
+
+        controller.init_progress(view)
+        self.assertTrue(view == controller.active_progress)
+
+        controller.begin()
+
+        self.assertEqual(controller.active_progress.string['message'], 'Starting')
+
+        controller.end()
+        self.assertEqual(controller.active_progress.string['message'], 'Finished')
+
+
+if __name__ == '__main__':
+    unittest.main()