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 <pre>
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 <paul.eggleton@linux.intel.com>

layerindex/static/css/additional.css

@@ -320,3 +320,8 @@ td.info {
     appearance: none;
   }
 }
+
+.vertical-scroll {
+    height: 400px;
+    overflow-y: scroll;
+}

layerindex/tasks.py

@@ -1,3 +1,10 @@
+# Celery task definitions for the layer index app
+#
+# Copyright (C) 2018 Intel Corporation
+# Author: Paul Eggleton <paul.eggleton@linux.intel.com>
+#
+# 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:

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)

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<task_id>[-\w]+)/$',
+            task_log_view,
+            name='task_log'),
     url(r'^ajax/layerchecklist/(?P<branch>[-\w]+)/$',
         LayerCheckListView.as_view(
             template_name='layerindex/layerchecklist.html'),

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,14 +285,18 @@ 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))
+    if outfile:
+        out = open(outfile, 'wb+')
+    else:
         out = tempfile.TemporaryFile()
+    try:
         try:
             subprocess.check_call(cmd, stdout=out, stderr=out, cwd=destdir, shell=True)
         except subprocess.CalledProcessError as e:
@@ -311,6 +316,9 @@ def runcmd(cmd, destdir=None, printerr=True, logger=None):
         output = output.decode('utf-8', errors='replace').strip()
         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'

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):

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 = ""

templates/layerindex/task.html

@@ -12,10 +12,6 @@
 {% endcomment %}
 
 
-{% block head_extra %}
-{% if not update.finished %}<meta http-equiv="refresh" content="5" />{% endif %}
-{% endblock %}
-
 <!--
 {% block title_append %} - task status{% endblock %}
 -->
@@ -23,13 +19,9 @@
 {% block content %}
 {% autoescape on %}
 
-<p>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%}:</p>
+<p>Task status for {{ update.task_id }} started by {{ update.triggered_by }} on {{ update.started }}<span id="task_status_fragment">{% if update.finished %} (finished in {{ update.started | timesince2:update.finished }}){% endif %}</span>:</p>
 
-{% if update.log %}
-<pre>{{ update.log }}</pre>
-{% else %}
-<p>{% if update.finished %}(no output){% else %}(no output - waiting for task to finish){% endif %}
-{% endif %}
+<pre id="task_log" class="vertical-scroll">{{ update.log }}</pre>
 
 {% if update.comparisonrecipeupdate_set.exists %}
 <h3>Updated comparison recipes</h3>
@@ -45,3 +37,45 @@
 
 {% block footer %}
 {% endblock %}
+
+{% block scripts %}
+<script>
+    var posn = 0;
+    var done = '0';
+    var duration = ''
+    var scrolling = true;
+
+    function updateLog() {
+        $.ajax({
+            url: '{{ log_url }}?start=' + posn,
+            success: function( data, code, xhr ) {
+                task_log = $("#task_log")
+                task_log.append(data);
+                if(scrolling) {
+                    task_log.animate({ scrollTop: task_log.prop('scrollHeight') }, "slow");
+                }
+                posn += data.length
+                done = xhr.getResponseHeader('Task-Done')
+                duration = xhr.getResponseHeader('Task-Duration')
+            }
+        }).always(function () {
+            if(done == '1') {
+                $("#task_status_fragment").html(" (finished in " + duration + ")")
+            }
+            else {
+                window.setTimeout(updateLog, 1000);
+            }
+        });
+    }
+
+    $("#task_log").scroll(function() {
+        scrolling = ($(this).scrollTop() + $(this).height() + 50 > $(this).prop('scrollHeight'))
+    });
+
+    $(document).ready(function() {
+        {% if not update.finished %}
+        updateLog();
+        {% endif %}
+    });
+</script>
+{% endblock %}