feat: add "progress" page for executing upgrades

show scrolling stdout from subprocess

nb. this does *not* show stderr, although that is captured

src/wuttaweb/templates/progress.mako

@@ -55,7 +55,7 @@
 <%def name="modify_vue_vars()">
   <script>
 
-    WholePageData.progressURL = '${url('progress', key=progress.key, _query={'sessiontype': progress.session.type})}'
+    WholePageData.progressURL = '${url('progress', key=progress.key)}'
     WholePageData.progressMessage = "${(initial_msg or "Working").replace('"', '\\"')} (please wait)"
     WholePageData.progressMax = null
     WholePageData.progressMaxDisplay = null
@@ -107,6 +107,9 @@
                     }
                 }
 
+                // custom logic if applicable
+                this.updateProgressCustom(response)
+
                 if (this.stillInProgress) {
 
                     // fetch progress data again, in one second from now
@@ -118,5 +121,7 @@
         })
     }
 
+    WholePage.methods.updateProgressCustom = function(response) {}
+
   </script>
 </%def>

src/wuttaweb/templates/upgrade.mako

@@ -0,0 +1,64 @@
+## -*- coding: utf-8; -*-
+<%inherit file="/progress.mako" />
+
+<%def name="extra_styles()">
+  ${parent.extra_styles()}
+  <style>
+
+    .upgrade-textout {
+        border: 1px solid Black;
+        line-height: 1.2;
+        margin-top: 1rem;
+        overflow: auto;
+        padding: 1rem;
+    }
+
+  </style>
+</%def>
+
+<%def name="after_progress()">
+  <div ref="textout"
+       class="upgrade-textout is-family-monospace is-size-7">
+    <span v-for="line in progressOutput"
+          :key="line.key"
+          v-html="line.text">
+    </span>
+
+    ## nb. we auto-scroll down to "see" this element
+    <div ref="seeme"></div>
+  </div>
+</%def>
+
+<%def name="modify_vue_vars()">
+  ${parent.modify_vue_vars()}
+  <script>
+
+    WholePageData.progressURL = '${url('upgrades.execute_progress', uuid=instance.uuid)}'
+    WholePageData.progressOutput = []
+    WholePageData.progressOutputCounter = 0
+
+    WholePageData.mountedHooks.push(function() {
+
+        // grow the textout area to fill most of screen
+        const textout = this.$refs.textout
+        const height = window.innerHeight - textout.offsetTop - 100
+        textout.style.height = height + 'px'
+    })
+
+    WholePage.methods.updateProgressCustom = function(response) {
+        if (response.data.stdout) {
+
+            // add lines to textout area
+            this.progressOutput.push({
+                key: ++this.progressOutputCounter,
+                text: response.data.stdout})
+
+            //  scroll down to end of textout area
+            this.$nextTick(() => {
+                this.$refs.seeme.scrollIntoView({behavior: 'smooth'})
+            })
+        }
+    }
+
+  </script>
+</%def>

src/wuttaweb/views/master.py

@@ -76,7 +76,7 @@ class MasterView(View):
        Optional reference to a data model class.  While not strictly
        required, most views will set this to a SQLAlchemy mapped
        class,
-       e.g. :class:`wuttjamaican:wuttjamaican.db.model.auth.User`.
+       e.g. :class:`~wuttjamaican:wuttjamaican.db.model.base.Person`.
 
        Code should not access this directly but instead call
        :meth:`get_model_class()`.
@@ -365,6 +365,7 @@ class MasterView(View):
     has_autocomplete = False
     downloadable = False
     executable = False
+    execute_progress_template = None
     configurable = False
 
     # current action
@@ -725,7 +726,7 @@ class MasterView(View):
                         len(records), model_title_plural,
                         exc_info=True)
             if progress:
-                progress.handle_error(error, "Bulk deletion failed")
+                progress.handle_error(error)
 
         else:
             session.commit()
@@ -953,21 +954,26 @@ class MasterView(View):
 
         * :meth:`execute_instance()`
         """
+        route_prefix = self.get_route_prefix()
         model_title = self.get_model_title()
         obj = self.get_instance()
 
-        try:
+        # make the progress tracker
-            self.execute_instance(obj)
+        progress = self.make_progress(f'{route_prefix}.execute',
-        except Exception as error:
+                                      success_msg=f"{model_title} was executed.",
-            log.exception("failed to execute %s: %s", model_title, obj)
+                                      success_url=self.get_action_url('view', obj))
-            error = str(error) or error.__class__.__name__
-            self.request.session.flash(error, 'error')
-        else:
-            self.request.session.flash(f"{model_title} was executed.")
 
-        return self.redirect(self.get_action_url('view', obj))
+        # start thread for execute; show progress page
+        key = self.request.matchdict
+        thread = threading.Thread(target=self.execute_thread,
+                                  args=(key, self.request.user.uuid),
+                                  kwargs={'progress': progress})
+        thread.start()
+        return self.render_progress(progress, context={
+            'instance': obj,
+        }, template=self.execute_progress_template)
 
-    def execute_instance(self, obj):
+    def execute_instance(self, obj, user, progress=None):
         """
         Perform the actual "execution" logic for a model record.
         Called by :meth:`execute()`.
@@ -975,8 +981,43 @@ class MasterView(View):
         This method does nothing by default; subclass must override.
 
         :param obj: Reference to the model instance.
+
+        :param user: Reference to the
+           :class:`~wuttjamaican:wuttjamaican.db.model.auth.User` who
+           is doing the execute.
+
+        :param progress: Optional progress indicator factory.
         """
 
+    def execute_thread(self, key, user_uuid, progress=None):
+        """ """
+        model = self.app.model
+        model_title = self.get_model_title()
+
+        # nb. use new session, separate from web transaction
+        session = self.app.make_session()
+
+        # fetch model instance and user for this session
+        obj = self.get_instance(session=session, matchdict=key)
+        user = session.get(model.User, user_uuid)
+
+        try:
+            self.execute_instance(obj, user, progress=progress)
+
+        except Exception as error:
+            session.rollback()
+            log.warning("%s failed to execute: %s", model_title, obj, exc_info=True)
+            if progress:
+                progress.handle_error(error)
+
+        else:
+            session.commit()
+            if progress:
+                progress.handle_success()
+
+        finally:
+            session.close()
+
     ##############################
     # configure methods
     ##############################
@@ -1847,23 +1888,69 @@ class MasterView(View):
         # for key in self.get_model_key():
         #     grid.set_link(key)
 
-    def get_instance(self, session=None):
+    def get_instance(self, session=None, matchdict=None):
         """
-        This should return the "current" model instance based on the
+        This should return the appropriate model instance, based on
-        request details (e.g. route kwargs).
+        the ``matchdict`` of model keys.
 
-        If the instance cannot be found, this should raise a HTTP 404
+        Normally this is called with no arguments, in which case the
-        exception, i.e. :meth:`~wuttaweb.views.base.View.notfound()`.
+        :attr:`pyramid:pyramid.request.Request.matchdict` is used, and
+        will return the "current" model instance based on the request
+        (route/params).
 
-        There is no "sane" default logic here; subclass *must*
+        If a ``matchdict`` is provided then that is used instead, to
-        override or else a ``NotImplementedError`` is raised.
+        obtain the model keys.  In the simple/common example of a
+        "native" model in WuttaWeb, this would look like::
+
+           keys = {'uuid': '38905440630d11ef9228743af49773a4'}
+           obj = self.get_instance(matchdict=keys)
+
+        Although some models may have different, possibly composite
+        key names to use instead.  The specific keys this logic is
+        expecting are the same as returned by :meth:`get_model_key()`.
+
+        If this method is unable to locate the instance, it should
+        raise a 404 error,
+        i.e. :meth:`~wuttaweb.views.base.View.notfound()`.
+
+        Default implementation of this method should work okay for
+        views which define a :attr:`model_class`.  For other views
+        however it will raise ``NotImplementedError``, so subclass
+        may need to define.
+
+        .. warning::
+
+           If you are defining this method for a subclass, please note
+           this point regarding the 404 "not found" logic.
+
+           It is *not* enough to simply *return* this 404 response,
+           you must explicitly *raise* the error.  For instance::
+
+              def get_instance(self, **kwargs):
+
+                  # ..try to locate instance..
+                  obj = self.locate_instance_somehow()
+
+                  if not obj:
+
+                      # NB. THIS MAY NOT WORK AS EXPECTED
+                      #return self.notfound()
+
+                      # nb. should always do this in get_instance()
+                      raise self.notfound()
+
+           This lets calling code not have to worry about whether or
+           not this method might return ``None``.  It can safely
+           assume it will get back a model instance, or else a 404
+           will kick in and control flow goes elsewhere.
         """
         model_class = self.get_model_class()
         if model_class:
             session = session or self.Session()
+            matchdict = matchdict or self.request.matchdict
 
             def filtr(query, model_key):
-                key = self.request.matchdict[model_key]
+                key = matchdict[model_key]
                 query = query.filter(getattr(self.model_class, model_key) == key)
                 return query
 
@@ -2126,7 +2213,7 @@ class MasterView(View):
         Returns the model class for the view (if defined).
 
         A model class will *usually* be a SQLAlchemy mapped class,
-        e.g. :class:`wuttjamaican:wuttjamaican.db.model.base.Person`.
+        e.g. :class:`~wuttjamaican:wuttjamaican.db.model.base.Person`.
 
         There is no default value here, but a subclass may override by
         assigning :attr:`model_class`.

src/wuttaweb/views/upgrades.py

@@ -36,6 +36,7 @@ from wuttjamaican.db.model import Upgrade
 from wuttaweb.views import MasterView
 from wuttaweb.forms import widgets
 from wuttaweb.forms.schema import UserRef, WuttaEnum, FileDownload
+from wuttaweb.progress import get_progress_session
 
 
 log = logging.getLogger(__name__)
@@ -57,6 +58,7 @@ class UpgradeView(MasterView):
     """
     model_class = Upgrade
     executable = True
+    execute_progress_template = '/upgrade.mako'
     downloadable = True
     configurable = True
 
@@ -222,7 +224,7 @@ class UpgradeView(MasterView):
             path = os.path.join(path, filename)
         return path
 
-    def execute_instance(self, upgrade):
+    def execute_instance(self, upgrade, user, progress=None):
         """
         This method runs the actual upgrade.
 
@@ -236,28 +238,79 @@ class UpgradeView(MasterView):
         either ``SUCCESS`` or ``FAILURE``.
         """
         enum = self.app.enum
-        script = self.config.require(f'{self.app.appname}.upgrades.command',
+
-                                     session=self.Session())
+        # locate file paths
+        script = self.config.require(f'{self.app.appname}.upgrades.command')
         stdout_path = self.get_upgrade_filepath(upgrade, 'stdout.log')
         stderr_path = self.get_upgrade_filepath(upgrade, 'stderr.log')
 
+        # record the fact that execution has begun for this upgrade
+        # nb. this is done in separate session to ensure it sticks,
+        # but also update local object to reflect the change
+        with self.app.short_session(commit=True) as s:
+            alt = s.merge(upgrade)
+            alt.status = enum.UpgradeStatus.EXECUTING
+        upgrade.status = enum.UpgradeStatus.EXECUTING
+
         # run the command
         log.debug("running upgrade command: %s", script)
         with open(stdout_path, 'wb') as stdout:
             with open(stderr_path, 'wb') as stderr:
-                upgrade.exit_code = subprocess.call(script, shell=True,
+                upgrade.exit_code = subprocess.call(script, shell=True, text=True,
                                                     stdout=stdout, stderr=stderr)
         logger = log.warning if upgrade.exit_code != 0 else log.debug
-        logger("upgrade command had non-zero exit code: %s", upgrade.exit_code)
+        logger("upgrade command had exit code: %s", upgrade.exit_code)
 
         # declare it complete
         upgrade.executed = datetime.datetime.now()
-        upgrade.executed_by = self.request.user
+        upgrade.executed_by = user
         if upgrade.exit_code == 0:
             upgrade.status = enum.UpgradeStatus.SUCCESS
         else:
             upgrade.status = enum.UpgradeStatus.FAILURE
 
+    def execute_progress(self):
+        """ """
+        route_prefix = self.get_route_prefix()
+        upgrade = self.get_instance()
+        session = get_progress_session(self.request, f'{route_prefix}.execute')
+
+        # session has 'complete' flag set when operation is over
+        if session.get('complete'):
+
+            # set a flash msg for user if one is defined.  this is the
+            # time to do it since user is about to get redirected.
+            msg = session.get('success_msg')
+            if msg:
+                self.request.session.flash(msg)
+
+        elif session.get('error'):  # uh-oh
+
+            # set an error flash msg for user.  this is the time to do it
+            # since user is about to get redirected.
+            msg = session.get('error_msg', "An unspecified error occurred.")
+            self.request.session.flash(msg, 'error')
+
+        # our return value will include all from progress session
+        data = dict(session)
+
+        # add whatever might be new from upgrade process STDOUT
+        path = self.get_upgrade_filepath(upgrade, filename='stdout.log')
+        offset = session.get('stdout.offset', 0)
+        if os.path.exists(path):
+            size = os.path.getsize(path) - offset
+            if size > 0:
+                # with open(path, 'rb') as f:
+                with open(path) as f:
+                    f.seek(offset)
+                    chunk = f.read(size)
+                    # data['stdout'] = chunk.decode('utf8').replace('\n', '<br />')
+                    data['stdout'] = chunk.replace('\n', '<br />')
+                session['stdout.offset'] = offset + size
+                session.save()
+
+        return data
+
     def configure_get_simple_settings(self):
         """ """
 
@@ -283,6 +336,21 @@ class UpgradeView(MasterView):
         cls.model_class = app.model.Upgrade
 
         cls._defaults(config)
+        cls._upgrade_defaults(config)
+
+    @classmethod
+    def _upgrade_defaults(cls, config):
+        route_prefix = cls.get_route_prefix()
+        permission_prefix = cls.get_permission_prefix()
+        instance_url_prefix = cls.get_instance_url_prefix()
+
+        # execution progress
+        config.add_route(f'{route_prefix}.execute_progress',
+                         f'{instance_url_prefix}/execute/progress')
+        config.add_view(cls, attr='execute_progress',
+                        route_name=f'{route_prefix}.execute_progress',
+                        permission=f'{permission_prefix}.execute',
+                        renderer='json')
 
 
 def defaults(config, **kwargs):

tests/views/test_master.py

@@ -1342,8 +1342,11 @@ class TestMasterView(WebTestCase):
 
     def test_execute(self):
         self.pyramid_config.add_route('settings.view', '/settings/{name}')
+        self.pyramid_config.add_route('progress', '/progress/{key}')
         model = self.app.model
         self.app.save_setting(self.session, 'foo', 'bar')
+        user = model.User(username='barney')
+        self.session.add(user)
         self.session.commit()
 
         with patch.multiple(mod.MasterView, create=True,
@@ -1352,18 +1355,54 @@ class TestMasterView(WebTestCase):
                             Session=MagicMock(return_value=self.session)):
             view = self.make_view()
             self.request.matchdict = {'name': 'foo'}
+            self.request.session.id = 'mockid'
+            self.request.user = user
 
-            # basic usage, redirects to view obj url
+            # basic usage; user is shown progress page
-            response = view.execute()
+            with patch.object(mod, 'threading') as threading:
-            self.assertEqual(response.status_code, 302)
-            self.assertEqual(self.request.session.pop_flash(), ["Setting was executed."])
-
-            # execution error
-            with patch.object(view, 'execute_instance', side_effect=RuntimeError):
                 response = view.execute()
-            self.assertEqual(response.status_code, 302)
+                threading.Thread.return_value.start.assert_called_once_with()
-            self.assertEqual(self.request.session.pop_flash(), [])
+                self.assertEqual(response.status_code, 200)
-            self.assertEqual(self.request.session.pop_flash('error'), ["RuntimeError"])
+
+    def test_execute_thread(self):
+        model = self.app.model
+        enum = self.app.enum
+        user = model.User(username='barney')
+        self.session.add(user)
+        upgrade = model.Upgrade(description='test', created_by=user,
+                                status=enum.UpgradeStatus.PENDING)
+        self.session.add(upgrade)
+        self.session.commit()
+
+        with patch.multiple(mod.MasterView, create=True,
+                            model_class=model.Upgrade):
+            view = self.make_view()
+
+            # basic execute, no progress
+            with patch.object(view, 'execute_instance') as execute_instance:
+                view.execute_thread({'uuid': upgrade.uuid}, user.uuid)
+                execute_instance.assert_called_once()
+
+            # basic execute, with progress
+            with patch.object(view, 'execute_instance') as execute_instance:
+                progress = MagicMock()
+                view.execute_thread({'uuid': upgrade.uuid}, user.uuid, progress=progress)
+                execute_instance.assert_called_once()
+                progress.handle_success.assert_called_once_with()
+
+            # error, no progress
+            with patch.object(view, 'execute_instance') as execute_instance:
+                execute_instance.side_effect = RuntimeError
+                view.execute_thread({'uuid': upgrade.uuid}, user.uuid)
+                execute_instance.assert_called_once()
+
+            # error, with progress
+            with patch.object(view, 'execute_instance') as execute_instance:
+                progress = MagicMock()
+                execute_instance.side_effect = RuntimeError
+                view.execute_thread({'uuid': upgrade.uuid}, user.uuid, progress=progress)
+                execute_instance.assert_called_once()
+                progress.handle_error.assert_called_once()
 
     def test_configure(self):
         self.pyramid_config.include('wuttaweb.views.common')

tests/views/test_upgrades.py

@@ -7,6 +7,7 @@ from unittest.mock import patch, MagicMock
 
 from wuttaweb.views import upgrades as mod
 from wuttjamaican.exc import ConfigurationError
+from wuttaweb.progress import get_progress_session
 from tests.util import WebTestCase
 
 
@@ -220,7 +221,7 @@ class TestUpgradeView(WebTestCase):
         python = sys.executable
 
         # script not yet confiugred
-        self.assertRaises(ConfigurationError, view.execute_instance, upgrade)
+        self.assertRaises(ConfigurationError, view.execute_instance, upgrade, user)
 
         # script w/ success
         goodpy = self.write_file('good.py', """
@@ -234,7 +235,7 @@ sys.exit(0)
         self.assertEqual(upgrade.status, enum.UpgradeStatus.PENDING)
         with patch.object(view, 'Session', return_value=self.session):
             with patch.object(self.config, 'usedb', new=True):
-                view.execute_instance(upgrade)
+                view.execute_instance(upgrade, user)
         self.assertIsNotNone(upgrade.executed)
         self.assertIs(upgrade.executed_by, user)
         self.assertEqual(upgrade.status, enum.UpgradeStatus.SUCCESS)
@@ -261,7 +262,7 @@ sys.exit(42)
         self.assertEqual(upgrade.status, enum.UpgradeStatus.PENDING)
         with patch.object(view, 'Session', return_value=self.session):
             with patch.object(self.config, 'usedb', new=True):
-                view.execute_instance(upgrade)
+                view.execute_instance(upgrade, user)
         self.assertIsNotNone(upgrade.executed)
         self.assertIs(upgrade.executed_by, user)
         self.assertEqual(upgrade.status, enum.UpgradeStatus.FAILURE)
@@ -270,6 +271,93 @@ sys.exit(42)
         with open(view.get_upgrade_filepath(upgrade, 'stderr.log')) as f:
             self.assertEqual(f.read(), 'hello from bad.py')
 
+    def test_execute_progress(self):
+        model = self.app.model
+        enum = self.app.enum
+        view = self.make_view()
+
+        user = model.User(username='barney')
+        self.session.add(user)
+        upgrade = model.Upgrade(description='test', created_by=user,
+                                status=enum.UpgradeStatus.PENDING)
+        self.session.add(upgrade)
+        self.session.commit()
+
+        stdout = self.write_file('stdout.log', 'hello 001\n')
+
+        self.request.matchdict = {'uuid': upgrade.uuid}
+        with patch.multiple(mod.UpgradeView,
+                            Session=MagicMock(return_value=self.session),
+                            get_upgrade_filepath=MagicMock(return_value=stdout)):
+
+            # nb. this is used to identify progress tracker
+            self.request.session.id = 'mockid#1'
+
+            # first call should get the full contents
+            context = view.execute_progress()
+            self.assertFalse(context.get('complete'))
+            self.assertFalse(context.get('error'))
+            # nb. newline is converted to <br>
+            self.assertEqual(context['stdout'], 'hello 001<br />')
+
+            # next call should get any new contents
+            with open(stdout, 'a') as f:
+                f.write('hello 002\n')
+            context = view.execute_progress()
+            self.assertFalse(context.get('complete'))
+            self.assertFalse(context.get('error'))
+            self.assertEqual(context['stdout'], 'hello 002<br />')
+
+            # nb. switch to a different progress tracker
+            self.request.session.id = 'mockid#2'
+
+            # first call should get the full contents
+            context = view.execute_progress()
+            self.assertFalse(context.get('complete'))
+            self.assertFalse(context.get('error'))
+            self.assertEqual(context['stdout'], 'hello 001<br />hello 002<br />')
+
+            # mark progress complete
+            session = get_progress_session(self.request, 'upgrades.execute')
+            session.load()
+            session['complete'] = True
+            session['success_msg'] = 'yay!'
+            session.save()
+
+            # next call should reflect that
+            self.assertEqual(self.request.session.pop_flash(), [])
+            context = view.execute_progress()
+            self.assertTrue(context.get('complete'))
+            self.assertFalse(context.get('error'))
+            # nb. this is missing b/c we already got all contents
+            self.assertNotIn('stdout', context)
+            self.assertEqual(self.request.session.pop_flash(), ['yay!'])
+
+            # nb. switch to a different progress tracker
+            self.request.session.id = 'mockid#3'
+
+            # first call should get the full contents
+            context = view.execute_progress()
+            self.assertFalse(context.get('complete'))
+            self.assertFalse(context.get('error'))
+            self.assertEqual(context['stdout'], 'hello 001<br />hello 002<br />')
+
+            # mark progress error
+            session = get_progress_session(self.request, 'upgrades.execute')
+            session.load()
+            session['error'] = True
+            session['error_msg'] = 'omg!'
+            session.save()
+
+            # next call should reflect that
+            self.assertEqual(self.request.session.pop_flash('error'), [])
+            context = view.execute_progress()
+            self.assertFalse(context.get('complete'))
+            self.assertTrue(context.get('error'))
+            # nb. this is missing b/c we already got all contents
+            self.assertNotIn('stdout', context)
+            self.assertEqual(self.request.session.pop_flash('error'), ['omg!'])
+
     def test_configure_get_simple_settings(self):
         # sanity/coverage check
         view = self.make_view()