def begin_user_activity(cls, user, activity_type="login", start_datetime=None):
        """Helper function to create a user activity log entry."""

        # Do nothing if the max # of records is zero or None
        # (i.e. this functionality is disabled)
        if not settings.USER_LOG_MAX_RECORDS:
            return

        assert user is not None, "A valid user must always be specified."
        if not start_datetime:  # must be done outside the function header (else becomes static)
            start_datetime = datetime.now()
        activity_type = cls.get_activity_int(activity_type)
        cur_user_log_entry = get_object_or_None(cls, user=user, end_datetime=None)

        logging.debug("%s: BEGIN activity(%d) @ %s" % (user.username, activity_type, start_datetime))

        # Seems we're logging in without logging out of the previous.
        #   Best thing to do is simulate a login
        #   at the previous last update time.
        #
        # Note: this can be a recursive call
        if cur_user_log_entry:
            logging.warn("%s: END activity on a begin @ %s" % (user.username, start_datetime))
            cls.end_user_activity(
                user=user, activity_type=activity_type, end_datetime=cur_user_log_entry.last_active_datetime
            )

        # Create a new entry
        cur_user_log_entry = cls(
            user=user, activity_type=activity_type, start_datetime=start_datetime, last_active_datetime=start_datetime
        )

        cur_user_log_entry.save()
        return cur_user_log_entry

    def end_user_activity(cls, user, activity_type="login", end_datetime=None):
        """Helper function to complete an existing user activity log entry."""

        # Do nothing if the max # of records is zero or None
        # (i.e. this functionality is disabled)
        if not settings.USER_LOG_MAX_RECORDS:
            return

        assert user is not None, "A valid user must always be specified."
        if not end_datetime:  # must be done outside the function header (else becomes static)
            end_datetime = datetime.now()
        activity_type = cls.get_activity_int(activity_type)

        cur_user_log_entry = get_object_or_None(cls, user=user, end_datetime=None)

        # No unstopped starts.  Start should have been called first!
        if not cur_user_log_entry:
            logging.warn(
                "%s: Had to create a user log entry, but STOPPING('%d')! @ %s"
                % (user.username, activity_type, end_datetime)
            )
            cur_user_log_entry = cls.begin_user_activity(
                user=user, activity_type=activity_type, start_datetime=end_datetime
            )

        logging.debug("%s: Logging LOGOUT activity @ %s" % (user.username, end_datetime))
        cur_user_log_entry.end_datetime = end_datetime
        cur_user_log_entry.save()  # total-seconds will be computed here.

    def end_user_activity(cls, user, activity_type="login", end_datetime=None, suppress_save=False):  # don't accept language--we're just closing previous activity.
        """Helper function to complete an existing user activity log entry."""

        # Do nothing if the max # of records is zero
        # (i.e. this functionality is disabled)
        if not cls.is_enabled():
            return

        if not user:
            raise ValidationError("A valid user must always be specified.")
        if not end_datetime:  # must be done outside the function header (else becomes static)
            end_datetime = datetime.now()
        activity_type = cls.get_activity_int(activity_type)

        cur_log = cls.get_latest_open_log_or_None(user=user, activity_type=activity_type)

        if cur_log:
            # How could you start after you ended??
            if cur_log.start_datetime > end_datetime:
                raise ValidationError("Update time must always be later than the login time.")
        else:
            # No unstopped starts.  Start should have been called first!
            logging.warn("%s: Had to BEGIN a user log entry, but ENDING(%d)! @ %s" % (user.username, activity_type, end_datetime))
            cur_log = cls.begin_user_activity(user=user, activity_type=activity_type, start_datetime=end_datetime, suppress_save=True)

        logging.debug("%s: Logging LOGOUT activity @ %s" % (user.username, end_datetime))
        cur_log.end_datetime = end_datetime
        if not suppress_save:
            cur_log.save()  # total-seconds will be computed here.
        return cur_log

    def add_log_to_summary(cls, user_log, device=None):
        """Adds total_time to the appropriate user/device/activity's summary log."""

        assert user_log.end_datetime, "all log items must have an end_datetime to be saved here."
        assert user_log.total_seconds >= 0, "all log items must have a non-negative total_seconds to be saved here."
        device = device or Device.get_own_device()  # Must be done here, or install fails

        # Check for an existing object
        log_summary = cls.objects.filter(
            device=device,
            user=user_log.user,
            activity_type=user_log.activity_type,
            start_datetime__lte=user_log.end_datetime,
            end_datetime__gte=user_log.end_datetime,
        )
        assert log_summary.count() <= 1, "There should never be multiple summaries in the same time period/device/user/type combo"

        # Get (or create) the log item
        log_summary = log_summary[0] if log_summary.count() else cls(
            device=device,
            user=user_log.user,
            activity_type=user_log.activity_type,
            start_datetime=cls.get_period_start_datetime(user_log.end_datetime, settings.USER_LOG_SUMMARY_FREQUENCY),
            end_datetime=cls.get_period_end_datetime(user_log.end_datetime, settings.USER_LOG_SUMMARY_FREQUENCY),
            total_seconds=0,
            count=0,
        )

        logging.debug("Adding %d seconds for %s/%s/%d, period %s to %s" % (user_log.total_seconds, device.name, user_log.user.username, user_log.activity_type, log_summary.start_datetime, log_summary.end_datetime))

        # Add the latest info
        log_summary.total_seconds += user_log.total_seconds
        log_summary.count += 1
        log_summary.save()

    def __init__(self, comment=None, fixture=None, **kwargs):

        self.return_dict = {}
        self.return_dict['comment'] = comment
        self.return_dict['class']=type(self).__name__
        self.return_dict['uname'] = platform.uname()
        self.return_dict['fixture'] = fixture
        try:
            self.verbosity = int(kwargs.get("verbosity"))
        except:
            self.verbosity = 1
                                
        try:
            branch = subprocess.Popen(["git", "describe", "--contains", "--all", "HEAD"], stdout=subprocess.PIPE).communicate()[0]
            self.return_dict['branch'] = branch[:-1]
            head = subprocess.Popen(["git", "log", "--pretty=oneline", "--abbrev-commit", "--max-count=1"], stdout=subprocess.PIPE).communicate()[0]
            self.return_dict['head'] = head[:-1]
        except:
            self.return_dict['branch'] = None
            self.return_dict['head'] = None            

        # if setup fails, what could we do?
        #   let the exception bubble up is the best.
        try:
            self._setup(**kwargs)
        except Exception as e:
            logging.debug("Failed setup (%s); trying to tear down" % e)
            try:
                self._teardown()
            except:
                pass
            raise e

def download_srt_from_3rd_party(*args, **kwargs):
    """Download subtitles specified by command line args"""

    lang_code = kwargs.get("lang_code", None)

    # if language specified, do those, if not do all
    if lang_code:
        srt_list_path = get_lang_map_filepath(lang_code)
        try:
            videos = json.loads(open(srt_list_path).read())
        except:
            raise LanguageCodeDoesNotExist(lang_code)
        download_if_criteria_met(videos, *args, **kwargs)

    else:
        for filename in get_all_download_status_files():
            try:
                videos = json.loads(open(filename).read())
            except Exception as e:
                logging.error(e)
                raise CommandError("Unable to open %s. The file might be corrupted. Please re-run the generate_subtitle_map command to regenerate it." % filename)
            
            try:
                kwargs["lang_code"] = os.path.basename(filename).split("_")[0]
                download_if_criteria_met(videos, *args, **kwargs)
            except Exception as e:
                logging.error(e)
                raise CommandError("Error while downloading language srts: %s" % e)

    def recurse_nodes_to_extract_knowledge_map(node, node_cache):
        """
        Internal function for recursing the topic tree and building the knowledge map.
        Requires rebranding of metadata done by recurse_nodes function.
        """
        assert node["kind"] == "Topic"

        if node.get("in_knowledge_map", None):
            if node["slug"] not in knowledge_map["topics"]:
                logging.debug("Not in knowledge map: %s" % node["slug"])
                node["in_knowledge_map"] = False
                for node in node_cache["Topic"][node["slug"]]:
                    node["in_knowledge_map"] = False

            knowledge_topics[node["slug"]] = topic_tools.get_all_leaves(node, leaf_type="Exercise")

            if not knowledge_topics[node["slug"]]:
                sys.stderr.write("Removing topic from topic tree: no exercises. %s" % node["slug"])
                del knowledge_topics[node["slug"]]
                del knowledge_map["topics"][node["slug"]]
                node["in_knowledge_map"] = False
                for node in node_cache["Topic"][node["slug"]]:
                    node["in_knowledge_map"] = False
        else:
            if node["slug"] in knowledge_map["topics"]:
                sys.stderr.write("Removing topic from topic tree; does not belong. '%s'" % node["slug"])
                logging.warn("Removing from knowledge map: %s" % node["slug"])
                del knowledge_map["topics"][node["slug"]]

        for child in [n for n in node.get("children", []) if n["kind"] == "Topic"]:
            recurse_nodes_to_extract_knowledge_map(child, node_cache)

def add_syncing_models(models):
    """When sync is run, these models will be sync'd"""

    get_foreign_key_classes = lambda m: set([field.rel.to for field in m._meta.fields if isinstance(field, ForeignKey)])

    for model in models:
        if model in _syncing_models:
            logging.warn("We are already syncing model %s" % unicode(model))
            continue

        # When we add models to be synced, we need to make sure
        #   that models that depend on other models are synced AFTER
        #   the model it depends on has been synced.

        # Get the dependencies of the new model
        foreign_key_classes = get_foreign_key_classes(model)

        # Find all the existing models that this new model refers to.
        class_indices = [_syncing_models.index(cls) for cls in foreign_key_classes if cls in _syncing_models]

        # Insert just after the last dependency found,
        #   or at the front if no dependencies
        insert_after_idx = 1 + (max(class_indices) if class_indices else -1)

        # Before inserting, make sure that any models referencing *THIS* model
        # appear after this model.
        if [True for synmod in _syncing_models[0 : insert_after_idx - 1] if model in get_foreign_key_classes(synmod)]:
            raise Exception("Dependency loop detected in syncing models; cannot proceed.")

        # Now we're ready to insert.
        _syncing_models.insert(insert_after_idx + 1, model)

def download_subtitle(youtube_id, lang_code, format="srt"):
    """Return subtitles for YouTube ID in language specified. Return False if they do not exist. Update local JSON accordingly."""
    assert format == "srt", "We only support srt download at the moment."

    api_info_map = json.loads(
        open(settings.SUBTITLES_DATA_ROOT + SRTS_JSON_FILENAME).read()
    )
    # get amara id
    amara_code = api_info_map.get(youtube_id).get("amara_code")

    # make request
    # Please see http://amara.readthedocs.org/en/latest/api.html
    base_url = "https://amara.org/api2/partners/videos"

    r = make_request(headers, "%s/%s/languages/%s/subtitles/?format=srt" % (
        base_url, amara_code, lang_code))
    if isinstance(r, basestring):
        return r
    else:
        # return the subtitle text, replacing empty subtitle lines with
        # spaces to make the FLV player happy
        try:
            r.encoding = "UTF-8"
            response = (r.text or u"") \
                .replace("\n\n\n", "\n   \n\n") \
                .replace("\r\n\r\n\r\n", "\r\n   \r\n\r\n")
        except Exception as e:
            logging.error(e)
            response = "client-error"
        return response

    def update_user_activity(cls, user, activity_type="login", update_datetime=None, language=None, suppress_save=False):
        """Helper function to update an existing user activity log entry."""

        # Do nothing if the max # of records is zero
        # (i.e. this functionality is disabled)
        if not cls.is_enabled():
            return

        if not user:
            raise ValidationError("A valid user must always be specified.")
        if not update_datetime:  # must be done outside the function header (else becomes static)
            update_datetime = datetime.now()
        activity_type = cls.get_activity_int(activity_type)

        cur_log = cls.get_latest_open_log_or_None(user=user, activity_type=activity_type)
        if cur_log:
            # How could you start after you updated??
            if cur_log.start_datetime > update_datetime:
                raise ValidationError("Update time must always be later than the login time.")
        else:
            # No unstopped starts.  Start should have been called first!
            logging.warn("%s: Had to create a user log entry on an UPDATE(%d)! @ %s" % (user.username, activity_type, update_datetime))
            cur_log = cls.begin_user_activity(user=user, activity_type=activity_type, start_datetime=update_datetime, suppress_save=True)

        logging.debug("%s: UPDATE activity (%d) @ %s" % (user.username, activity_type, update_datetime))
        cur_log.last_active_datetime = update_datetime
        cur_log.language = language or cur_log.language  # set the language to the current language, if there is one.
        if not suppress_save:
            cur_log.save()
        return cur_log

def add_to_summary(sender, **kwargs):
    assert UserLog.is_enabled(), "We shouldn't be saving unless UserLog is enabled."

    instance = kwargs["instance"]

    if not instance.start_datetime:
        raise ValidationError("start_datetime cannot be None")
    if instance.last_active_datetime and instance.start_datetime > instance.last_active_datetime:
        raise ValidationError("UserLog date consistency check for start_datetime and last_active_datetime")

    if instance.end_datetime and not instance.total_seconds:
        # Compute total_seconds, save to summary
        #   Note: only supports setting end_datetime once!
        instance.full_clean()

        # The top computation is more lenient: user activity is just time logged in, literally.
        # The bottom computation is more strict: user activity is from start until the last "action"
        #   recorded--in the current case, that means from login until the last moment an exercise or
        #   video log was updated.
        #instance.total_seconds = datediff(instance.end_datetime, instance.start_datetime, units="seconds")
        instance.total_seconds = 0 if not instance.last_active_datetime else datediff(instance.last_active_datetime, instance.start_datetime, units="seconds")

        # Confirm the result (output info first for easier debugging)
        if instance.total_seconds < 0:
            raise ValidationError("Total learning time should always be non-negative.")
        logging.debug("%s: total time (%d): %d seconds" % (instance.user.username, instance.activity_type, instance.total_seconds))

        # Save only completed log items to the UserLogSummary
        UserLogSummary.add_log_to_summary(instance)

def generate_fake_coachreport_logs(password="hellothere"):
    t,_ = FacilityUser.objects.get_or_create(
        facility=Facility.objects.all()[0],
        username=random.choice(firstnames)
    )
    t.set_password(password)

    # TODO: create flags later
    num_logs = 20
    logs = []
    for _ in xrange(num_logs):
        date_logged_in = datetime.datetime.now() - datetime.timedelta(days=random.randint(1,10))
        date_viewed_coachreport = date_logged_in + datetime.timedelta(minutes=random.randint(0, 30))
        date_logged_out = date_viewed_coachreport + datetime.timedelta(minutes=random.randint(0, 30))
        login_log = UserLog.objects.create(
            user=t,
            activity_type=UserLog.get_activity_int("login"),
            start_datetime=date_logged_in,
            last_active_datetime=date_viewed_coachreport,
            end_datetime=date_logged_out,
        )
        logging.info("created login log for teacher %s" % t.username)
        coachreport_log = UserLog.objects.create(
            user=t,
            activity_type=UserLog.get_activity_int("coachreport"),
            start_datetime=date_viewed_coachreport,
            last_active_datetime=date_viewed_coachreport,
            end_datetime=date_viewed_coachreport,
        )
        logs.append((login_log, coachreport_log))
        logging.info("created coachreport log for teacher %s" % t.username)
    return logs

 def process_request(self, request):
     next = request.GET.get("next", "")
     if next.startswith("/"):
         logging.debug("next='%s'" % next)
         request.next = next
     else:
         request.next = ""

    def recurse_nodes_to_delete_exercise(node, OLD_NODE_CACHE):
        """
        Internal function for recursing the topic tree and removing new exercises.
        Requires rebranding of metadata done by recurse_nodes function.
        """
        # Stop recursing when we hit leaves
        if node["kind"] != "Topic":
            return

        children_to_delete = []
        for ci, child in enumerate(node.get("children", [])):
            # Mark all unrecognized exercises for deletion
            if child["kind"] == "Exercise":
                if not child["slug"] in OLD_NODE_CACHE["Exercise"].keys():
                    children_to_delete.append(ci)
            # Recurse over children to delete
            elif child.get("children", None):
                recurse_nodes_to_delete_exercise(child, OLD_NODE_CACHE)
                # Delete children without children (all their children were removed)
                if not child.get("children", None):
                    logging.debug("Removing now-childless topic node '%s'" % child["slug"])
                    children_to_delete.append(ci)
                # If there are no longer exercises, be honest about it
                elif not any([ch["kind"] == "Exercise" or "Exercise" in ch.get("contains", []) for ch in child["children"]]):
                    child["contains"] = list(set(child["contains"]) - set(["Exercise"]))

        # Do the actual deletion
        for i in reversed(children_to_delete):
            logging.debug("Deleting unknown exercise %s" % node["children"][i]["slug"])
            del node["children"][i]

def zip_language_packs(lang_codes=None):
    """Zip up and expose all language packs

    converts all into ietf
    """

    lang_codes = lang_codes or os.listdir(LOCALE_ROOT)
    lang_codes = [lcode_to_ietf(lc) for lc in lang_codes]
    logging.info("Zipping up %d language pack(s)" % len(lang_codes))

    for lang_code_ietf in lang_codes:
        lang_code_django = lcode_to_django_dir(lang_code_ietf)
        lang_locale_path = os.path.join(LOCALE_ROOT, lang_code_django)

        if not os.path.exists(lang_locale_path):
            logging.warn("Unexpectedly skipping missing directory: %s" % lang_code_django)
        elif not os.path.isdir(lang_locale_path):
            logging.error("Skipping language where a file exists where a directory was expected: %s" % lang_code_django)

        # Create a zipfile for this language
        zip_filepath = get_language_pack_filepath(lang_code_ietf)
        ensure_dir(os.path.dirname(zip_filepath))
        logging.info("Creating zip file in %s" % zip_filepath)
        z = zipfile.ZipFile(zip_filepath, 'w', zipfile.ZIP_DEFLATED)

        # Get every single file in the directory and zip it up
        for metadata_file in glob.glob('%s/*.json' % lang_locale_path):
            z.write(os.path.join(lang_locale_path, metadata_file), arcname=os.path.basename(metadata_file))

        srt_dirpath = get_srt_path(lang_code_django)
        for srt_file in glob.glob(os.path.join(srt_dirpath, "*.srt")):
            z.write(srt_file, arcname=os.path.join("subtitles", os.path.basename(srt_file)))
        z.close()
    logging.info("Done.")

def login(request, facility):
    facility_id = facility and facility.id or None
    facilities = list(Facility.objects.all())

    # Fix for #1211: refresh cached facility info when it's free and relevant
    refresh_session_facility_info(request, facility_count=len(facilities))

    if request.method == 'POST':
        # log out any Django user or facility user
        logout(request)

        username = request.POST.get("username", "")
        password = request.POST.get("password", "")

        # first try logging in as a Django user
        user = authenticate(username=username, password=password)
        if user:
            auth_login(request, user)
            return HttpResponseRedirect(request.next or reverse("easy_admin"))

        # try logging in as a facility user
        form = LoginForm(data=request.POST, request=request, initial={"facility": facility_id})
        if form.is_valid():
            user = form.get_user()

            try:
                UserLog.begin_user_activity(user, activity_type="login", language=request.language)  # Success! Log the event (ignoring validation failures)
            except ValidationError as e:
                logging.error("Failed to begin_user_activity upon login: %s" % e)

            request.session["facility_user"] = user
            messages.success(request, _("You've been logged in! We hope you enjoy your time with KA Lite ") +
                                        _("-- be sure to log out when you finish."))

            # Send them back from whence they came
            landing_page = form.cleaned_data["callback_url"]
            if not landing_page:
                # Just going back to the homepage?  We can do better than that.
                landing_page = reverse("coach_reports") if form.get_user().is_teacher else None
                landing_page = landing_page or (reverse("account_management") if not settings.package_selected("RPi") else reverse("homepage"))

            return HttpResponseRedirect(form.non_field_errors() or request.next or landing_page)

        else:
            messages.error(
                request,
                _("There was an error logging you in. Please correct any errors listed below, and try again."),
            )

    else:  # render the unbound login form
        referer = urlparse.urlparse(request.META["HTTP_REFERER"]).path if request.META.get("HTTP_REFERER") else None
        # never use the homepage as the referer
        if referer in [reverse("homepage"), reverse("add_facility_student")]:
            referer = None
        form = LoginForm(initial={"facility": facility_id, "callback_url": referer})

    return {
        "form": form,
        "facilities": facilities,
    }

        def validate_times(srt_content, srt_issues):
            times = re.findall("([0-9:,]+) --> ([0-9:,]+)\r\n", srt_content, re.S | re.M)

            parse_time = lambda str: datetime.datetime.strptime(str, "%H:%M:%S,%f")
            for i in range(len(times)):
                try:
                    between_subtitle_time = datediff(parse_time(times[i][0]), parse_time(times[i-1][1] if i > 0 else "00:00:00,000"))
                    within_subtitle_time  = datediff(parse_time(times[i][1]), parse_time(times[i][0]))

                    if between_subtitle_time > 60.:
                        srt_issues.append("Between-subtitle gap of %5.2f seconds" % between_subtitle_time)

                    if within_subtitle_time > 60.:
                        srt_issues.append("Within-subtitle duration of %5.2f seconds" % within_subtitle_time)
                    elif within_subtitle_time == 0.:
                        logging.debug("Subtitle flies by too fast (%s --> %s)." % times[i])

                    #print "Start: %s\tB: %5.2f\tW: %5.2f" % (parse_time(times[i][0]), between_subtitle_time, within_subtitle_time)
                except Exception as e:
                    if not times[i][1].startswith('99:59:59'):
                        srt_issues.append("Error checking times: %s" % e)
                    else:
                        if len(times) - i > 1 and len(times) - i - 1 > len(times)/10.:
                            if i == 0:
                                srt_issues.append("No subtitles have a valid starting point.")
                            else:
                                logging.debug("Hit end of movie, but %d (of %d) subtitle(s) remain in the queue." % (len(times) - i - 1, len(times)))
                        break

def call_outside_command_with_output(kalite_location, command, *args, **kwargs):
    """
    Runs call_command for a KA Lite installation at the given location,
    and returns the output.
    """

    # build the command
    cmd = (sys.executable,kalite_location + "/kalite/manage.py",command)
    for arg in args:
        cmd += (arg,)
    for key,val in kwargs.items():
        key = key.replace("_","-")
        prefix = "--" if command != "runcherrypyserver" else ""
        if isinstance(val,bool):
            cmd += ("%s%s" % (prefix,key),)
        else:
            cmd += ("%s%s=%s" % (prefix,key,str(val)),)

    logging.debug(cmd)

    # Execute the command, using subprocess/Popen
    cwd = os.getcwd()
    os.chdir(kalite_location + "/kalite")
    p = subprocess.Popen(cmd, shell=False, cwd=os.path.split(cmd[0])[0], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
    out = p.communicate()
    os.chdir(cwd)

    logging.debug(out[1] if out[1] else out[0])

    # tuple output of stdout, stderr, and exit code
    return out + (1 if out[1] else 0,)

    def handle(self, *args, **options):

        if len(args)==1 and args[0]== "test":
            # Callback for "weak" test--checks at least that the django project compiles (local_settings is OK)
            sys.stdout.write("Success!\n")
            exit(0)

        try:
            if options.get("branch", None):
                # Specified a repo
                self.update_via_git(**options)

            elif options.get("zip_file", None):
                # Specified a file
                if not os.path.exists(options.get("zip_file")):
                    raise CommandError("Specified zip file does not exist: %s" % options.get("zip_file"))
                self.update_via_zip(**options)

            elif options.get("url", None):
                self.update_via_zip(**options)

            elif os.path.exists(settings.PROJECT_PATH + "/../.git"):
                # If we detect a git repo, try git
                if len(args) == 1 and not options["branch"]:
                    options["branch"] = args[0]
                elif len(args) != 0:
                    raise CommandError("Specified too many command-line arguments")
                self.update_via_git(**options)

            elif len(args) > 1:
                raise CommandError("Too many command-line arguments.")

            elif len(args) == 1:
                # Specify zip via first command-line arg
                if options['zip_file'] is not None:
                    raise CommandError("Cannot specify a zipfile as unnamed and named command-line arguments at the same time.")
                options['zip_file'] = args[0]
                self.update_via_zip(**options)

            else:
                # No params, no git repo: try to get a file online.
                zip_file = tempfile.mkstemp()[1]
                for url in ["http://%s/api/download/kalite/latest/%s/%s/" % (settings.CENTRAL_SERVER_HOST, platform.system().lower(), "en")]:
                    logging.info("Downloading repo snapshot from %s to %s" % (url, zip_file))
                    try:
                        urllib.urlretrieve(url, zip_file)
                        sys.stdout.write("success @ %s\n" % url)
                        break;
                    except Exception as e:
                        logging.debug("Failed to get zipfile from %s: %s" % (url, e))
                        continue
                options["zip_file"] = zip_file
                self.update_via_zip(**options)

        except Exception as e:
            if self.started() and not not self.ended():
                self.cancel(stage_status="error", notes=unicode(e))
            raise

        assert self.ended(), "Subroutines should complete() if they start()!"

    def begin_user_activity(cls, user, activity_type="login", start_datetime=None, language=None, suppress_save=False):
        """Helper function to create a user activity log entry."""

        # Do nothing if the max # of records is zero
        # (i.e. this functionality is disabled)
        if not cls.is_enabled():
            return

        if not user:
            raise ValidationError("A valid user must always be specified.")
        if not start_datetime:  # must be done outside the function header (else becomes static)
            start_datetime = datetime.now()
        activity_type = cls.get_activity_int(activity_type)

        cur_log = cls.get_latest_open_log_or_None(user=user, activity_type=activity_type)
        if cur_log:
            # Seems we're logging in without logging out of the previous.
            #   Best thing to do is simulate a login
            #   at the previous last update time.
            #
            # Note: this can be a recursive call
            logging.warn("%s: had to END activity on a begin(%d) @ %s" % (user.username, activity_type, start_datetime))
            # Don't mark current language when closing an old one
            cls.end_user_activity(user=user, activity_type=activity_type, end_datetime=cur_log.last_active_datetime)  # can't suppress save
            cur_log = None

        # Create a new entry
        logging.debug("%s: BEGIN activity(%d) @ %s" % (user.username, activity_type, start_datetime))
        cur_log = cls(user=user, activity_type=activity_type, start_datetime=start_datetime, last_active_datetime=start_datetime, language=language)
        if not suppress_save:
            cur_log.save()

        return cur_log