From 74b1b9c895816fba9cd0d2e1ccc382e3f268e09b Mon Sep 17 00:00:00 2001 From: Paul Eggleton Date: Mon, 10 Sep 2018 16:46:12 +1200 Subject: [PATCH] Show update task output more smoothly We were refreshing the page constantly in order to show output while a task was running, which basically worked but is horrible. Instead, write the task output to a file and then use AJAX calls to request whatever output has been written to the file since the last call and call this roughly every second. Put the output in a scrollable 
element instead of making it the length of the page, and auto-scroll
to the end (unless the user grabs the scrollbar and pulls it upwards -
it may not be immediately obvious that you can do this if there is a lot
of output since you have to pull it up when the scrolling animation is
not running, but it is possible).

An alternative would be to have used some kind of long-lived HTTP
session or a websocket, but those come with their own set of problems
so I elected to use this much simpler method.

Signed-off-by: Paul Eggleton 
---
 layerindex/static/css/additional.css    |  5 ++
 layerindex/tasks.py                     | 14 +++++-
 layerindex/templatetags/extrafilters.py | 21 +--------
 layerindex/urls.py                      |  5 +-
 layerindex/utils.py                     | 63 ++++++++++++++++++-------
 layerindex/views.py                     | 33 ++++++++++++-
 settings.py                             |  3 ++
 templates/layerindex/task.html          | 54 +++++++++++++++++----
 8 files changed, 147 insertions(+), 51 deletions(-)

diff --git a/layerindex/static/css/additional.css b/layerindex/static/css/additional.css
index 185e2f8..dc48971 100644
--- a/layerindex/static/css/additional.css
+++ b/layerindex/static/css/additional.css
@@ -320,3 +320,8 @@ td.info {
     appearance: none;
   }
 }
+
+.vertical-scroll {
+    height: 400px;
+    overflow-y: scroll;
+}
diff --git a/layerindex/tasks.py b/layerindex/tasks.py
index 8fdb736..7ed0663 100644
--- a/layerindex/tasks.py
+++ b/layerindex/tasks.py
@@ -1,3 +1,10 @@
+# Celery task definitions for the layer index app
+#
+# Copyright (C) 2018 Intel Corporation
+# Author: Paul Eggleton 
+#
+# Licensed under the MIT license, see COPYING.MIT for details
+
 from celery import Celery
 from django.core.mail import EmailMessage
 from . import utils
@@ -36,7 +43,12 @@ def run_update_command(self, branch_name, update_command):
     update_command = update_command.replace('%update%', str(updateobj.id))
     update_command = update_command.replace('%branch%', branch_name)
     try:
-        output = utils.runcmd(update_command, os.path.dirname(os.path.dirname(__file__)))
+        os.makedirs(settings.TASK_LOG_DIR)
+    except FileExistsError:
+        pass
+    logfile = os.path.join(settings.TASK_LOG_DIR, 'task_%s.log' % str(self.request.id))
+    try:
+        output = utils.runcmd(update_command, os.path.dirname(os.path.dirname(__file__)), outfile=logfile)
     except subprocess.CalledProcessError as e:
         output = e.output
     except Exception as e:
diff --git a/layerindex/templatetags/extrafilters.py b/layerindex/templatetags/extrafilters.py
index c061a94..d79f9a1 100644
--- a/layerindex/templatetags/extrafilters.py
+++ b/layerindex/templatetags/extrafilters.py
@@ -1,4 +1,3 @@
-from datetime import datetime
 from django import template
 from .. import utils
 
@@ -18,22 +17,4 @@ def truncatesimple(strval, length):
 
 @register.filter
 def timesince2(date, date2=None):
-    # Based on http://www.didfinishlaunchingwithoptions.com/a-better-timesince-template-filter-for-django/
-    if date2 is None:
-        date2 = datetime.now()
-    if date > date2:
-        return '0 seconds'
-    diff = date2 - date
-    periods = (
-        (diff.days // 365, 'year', 'years'),
-        (diff.days // 30, 'month', 'months'),
-        (diff.days // 7, 'week', 'weeks'),
-        (diff.days, 'day', 'days'),
-        (diff.seconds // 3600, 'hour', 'hours'),
-        (diff.seconds // 60, 'minute', 'minutes'),
-        (diff.seconds, 'second', 'seconds'),
-    )
-    for period, singular, plural in periods:
-        if period:
-            return '%d %s' % (period, singular if period == 1 else plural)
-    return '0 seconds'
+    return utils.timesince2(date, date2)
diff --git a/layerindex/urls.py b/layerindex/urls.py
index 9f9a74e..e8ba8c9 100644
--- a/layerindex/urls.py
+++ b/layerindex/urls.py
@@ -8,7 +8,7 @@ from django.conf.urls import *
 from django.views.generic import TemplateView, DetailView, ListView, RedirectView
 from django.views.defaults import page_not_found
 from django.core.urlresolvers import reverse_lazy
-from layerindex.views import LayerListView, LayerReviewListView, LayerReviewDetailView, RecipeSearchView, MachineSearchView, LayerDetailView, edit_layer_view, delete_layer_view, edit_layernote_view, delete_layernote_view, HistoryListView, EditProfileFormView, AdvancedRecipeSearchView, BulkChangeView, BulkChangeSearchView, bulk_change_edit_view, bulk_change_patch_view, BulkChangeDeleteView, RecipeDetailView, RedirectParamsView, ClassicRecipeSearchView, ClassicRecipeDetailView, ClassicRecipeStatsView, LayerUpdateDetailView, UpdateListView, UpdateDetailView, StatsView, publish_view, LayerCheckListView, BBClassCheckListView, TaskStatusView, ComparisonRecipeSelectView, ComparisonRecipeSelectDetailView
+from layerindex.views import LayerListView, LayerReviewListView, LayerReviewDetailView, RecipeSearchView, MachineSearchView, LayerDetailView, edit_layer_view, delete_layer_view, edit_layernote_view, delete_layernote_view, HistoryListView, EditProfileFormView, AdvancedRecipeSearchView, BulkChangeView, BulkChangeSearchView, bulk_change_edit_view, bulk_change_patch_view, BulkChangeDeleteView, RecipeDetailView, RedirectParamsView, ClassicRecipeSearchView, ClassicRecipeDetailView, ClassicRecipeStatsView, LayerUpdateDetailView, UpdateListView, UpdateDetailView, StatsView, publish_view, LayerCheckListView, BBClassCheckListView, TaskStatusView, ComparisonRecipeSelectView, ComparisonRecipeSelectDetailView, task_log_view
 from layerindex.models import LayerItem, Recipe, RecipeChangeset
 from rest_framework import routers
 from . import restviews
@@ -168,6 +168,9 @@ urlpatterns = [
         TaskStatusView.as_view(
             template_name='layerindex/task.html'),
             name='task_status'),
+    url(r'^tasklog/(?P[-\w]+)/$',
+            task_log_view,
+            name='task_log'),
     url(r'^ajax/layerchecklist/(?P[-\w]+)/$',
         LayerCheckListView.as_view(
             template_name='layerindex/layerchecklist.html'),
diff --git a/layerindex/utils.py b/layerindex/utils.py
index 63759f2..b1544fb 100644
--- a/layerindex/utils.py
+++ b/layerindex/utils.py
@@ -15,6 +15,7 @@ import fcntl
 import signal
 import codecs
 import re
+from datetime import datetime
 from bs4 import BeautifulSoup
 
 def get_branch(branchname):
@@ -284,33 +285,40 @@ def parse_layer_conf(layerdir, data, logger=None):
     data = parse_conf(conf_file, data)
     data.expandVarref('LAYERDIR')
 
-def runcmd(cmd, destdir=None, printerr=True, logger=None):
+def runcmd(cmd, destdir=None, printerr=True, outfile=None, logger=None):
     """
         execute command, raise CalledProcessError if fail
         return output if succeed
     """
     if logger:
         logger.debug("run cmd '%s' in %s" % (cmd, os.getcwd() if destdir is None else destdir))
-    out = tempfile.TemporaryFile()
+    if outfile:
+        out = open(outfile, 'wb+')
+    else:
+        out = tempfile.TemporaryFile()
     try:
-        subprocess.check_call(cmd, stdout=out, stderr=out, cwd=destdir, shell=True)
-    except subprocess.CalledProcessError as e:
+        try:
+            subprocess.check_call(cmd, stdout=out, stderr=out, cwd=destdir, shell=True)
+        except subprocess.CalledProcessError as e:
+            out.seek(0)
+            output = out.read()
+            output = output.decode('utf-8', errors='replace').strip()
+            if printerr:
+                if logger:
+                    logger.error("%s" % output)
+                else:
+                    sys.stderr.write("%s\n" % output)
+            e.output = output
+            raise e
+
         out.seek(0)
         output = out.read()
         output = output.decode('utf-8', errors='replace').strip()
-        if printerr:
-            if logger:
-                logger.error("%s" % output)
-            else:
-                sys.stderr.write("%s\n" % output)
-        e.output = output
-        raise e
-
-    out.seek(0)
-    output = out.read()
-    output = output.decode('utf-8', errors='replace').strip()
-    if logger:
-        logger.debug("output: %s" % output.rstrip() )
+        if logger:
+            logger.debug("output: %s" % output.rstrip() )
+    finally:
+        if outfile:
+            out.close()
     return output
 
 def setup_django():
@@ -431,3 +439,24 @@ def sanitise_html(html):
 
 def squashspaces(string):
     return re.sub("\s+", " ", string).strip()
+
+def timesince2(date, date2=None):
+    # Based on http://www.didfinishlaunchingwithoptions.com/a-better-timesince-template-filter-for-django/
+    if date2 is None:
+        date2 = datetime.now()
+    if date > date2:
+        return '0 seconds'
+    diff = date2 - date
+    periods = (
+        (diff.days // 365, 'year', 'years'),
+        (diff.days // 30, 'month', 'months'),
+        (diff.days // 7, 'week', 'weeks'),
+        (diff.days, 'day', 'days'),
+        (diff.seconds // 3600, 'hour', 'hours'),
+        (diff.seconds // 60, 'minute', 'minutes'),
+        (diff.seconds, 'second', 'seconds'),
+    )
+    for period, singular, plural in periods:
+        if period:
+            return '%d %s' % (period, singular if period == 1 else plural)
+    return '0 seconds'
diff --git a/layerindex/views.py b/layerindex/views.py
index 55a3633..3302054 100644
--- a/layerindex/views.py
+++ b/layerindex/views.py
@@ -5,6 +5,7 @@
 # Licensed under the MIT license, see COPYING.MIT for details
 
 import sys
+import os
 from pkg_resources import parse_version
 from itertools import islice
 from django.shortcuts import get_object_or_404, get_list_or_404, render
@@ -29,6 +30,8 @@ from django.utils.decorators import method_decorator
 from django.contrib.auth.decorators import login_required
 from django.contrib import messages
 from django import forms
+from django.utils.html import escape
+
 from reversion.models import Revision
 from . import utils
 from . import simplesearch
@@ -225,8 +228,6 @@ def bulk_change_edit_view(request, template_name, pk):
     })
 
 def bulk_change_patch_view(request, pk):
-    import os
-    import os.path
     changeset = get_object_or_404(RecipeChangeset, pk=pk)
     # FIXME this couples the web server and machine running the update script together,
     # but given that it's a separate script the way is open to decouple them in future
@@ -1372,8 +1373,36 @@ class TaskStatusView(TemplateView):
         context['task_id'] = task_id
         context['result'] = AsyncResult(task_id)
         context['update'] = get_object_or_404(Update, task_id=task_id)
+        context['log_url'] = reverse_lazy('task_log', args=(task_id,))
         return context
 
+def task_log_view(request, task_id):
+    from celery.result import AsyncResult
+    if not request.user.is_authenticated():
+        raise PermissionDenied
+
+    if '/' in task_id:
+        # Block anything that looks like a path
+        raise Http404
+
+    result = AsyncResult(task_id)
+    start = request.GET.get('start', 0)
+    try:
+        f = open(os.path.join(settings.TASK_LOG_DIR, 'task_%s.log' % task_id), 'rb')
+    except FileNotFoundError:
+        raise Http404
+    f.seek(int(start))
+    # We need to escape this or else things that look like tags in the output
+    # will be interpreted as such by the browser
+    data = escape(f.read())
+    response = HttpResponse(data)
+    if result.ready():
+        response['Task-Done'] = '1'
+        updateobj = get_object_or_404(Update, task_id=task_id)
+        response['Task-Duration'] = utils.timesince2(updateobj.started, updateobj.finished)
+    else:
+        response['Task-Done'] = '0'
+    return response
 
 class ComparisonRecipeSelectView(ClassicRecipeSearchView):
     def _can_edit(self):
diff --git a/settings.py b/settings.py
index 981adfb..a456eb7 100644
--- a/settings.py
+++ b/settings.py
@@ -238,5 +238,8 @@ RABBIT_BACKEND = 'rpc://'
 # Used for fetching repo
 PARALLEL_JOBS = "4"
 
+# Full path to directory to store logs for dynamically executed tasks
+TASK_LOG_DIR = "/tmp/layerindex-task-logs"
+
 # Full path to directory where rrs tools stores logs
 TOOLS_LOG_DIR = ""
diff --git a/templates/layerindex/task.html b/templates/layerindex/task.html
index 371945e..c2e9c28 100644
--- a/templates/layerindex/task.html
+++ b/templates/layerindex/task.html
@@ -12,10 +12,6 @@
 {% endcomment %}
 
 
-{% block head_extra %}
-{% if not update.finished %}{% endif %}
-{% endblock %}
-
 
@@ -23,13 +19,9 @@
 {% block content %}
 {% autoescape on %}
 
-
Task status for {{ update.task_id }} started by {{ update.triggered_by }} {% if update.finished %} on {{ update.started }} (finished in {{ update.started | timesince2:update.finished }}){% else %}{{ update.started | timesince2 }} ago{% endif%}:

+
Task status for {{ update.task_id }} started by {{ update.triggered_by }} on {{ update.started }}{% if update.finished %} (finished in {{ update.started | timesince2:update.finished }}){% endif %}:

 
-{% if update.log %}
-
{{ update.log }}

-{% else %}
-
{% if update.finished %}(no output){% else %}(no output - waiting for task to finish){% endif %}
-{% endif %}
+
{{ update.log }}

 
 {% if update.comparisonrecipeupdate_set.exists %}
 
Updated comparison recipes

@@ -45,3 +37,45 @@
 
 {% block footer %}
 {% endblock %}
+
+{% block scripts %}
+
+{% endblock %}