Beispiel #1
0
def _process_fileset_task(list_of_file_dict, lockfile, lock_id):
    '''
    Hands the list to a recursive celery task function.
    The recursion continues until the list is empty.  The calling
    function exits immediately.
    '''
    logid = {'logid': "%s" % (lockfile)}
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name, extra=logid)

    # Create a lock file here to block any other actions on this report (see TS-8411)
    locallock = TaskLock(lock_id, timeout=60)  # short timeout in case lock release code doesn't get called

    if not(locallock.lock()):
        logger.warn("lock file exists: %s(%s)" % (lock_id, locallock.get()), extra=logid)
        # Release the task lock
        try:
            applock = TaskLock(lockfile)
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra=logid)
        return

    logger.info("lock file created: %s(%s)" % (lock_id, locallock.get()), extra=logid)

    # lockfile variable stored in list_of_file_dict
    for entry in list_of_file_dict:
        entry['lockfile'] = lockfile

    try:
        pfilename = set_action_param_var(list_of_file_dict)

        # Call the recursive celery task function to process the list
        _process_task.delay(pfilename)

    except:
        logger.error("We got an error here, _process_fileset_task", extra=logid)
        raise
    finally:
        if locallock:
            locallock.unlock()

    return
Beispiel #2
0
def manage_manual_action():
    logid = {'logid': "%s" % ('manual_action')}
    logger.debug("manage_manual_action", extra=logid)

    def getfirstmanualaction():
        manual_selects = DMFileStat.objects.filter(action_state__in=['SA', 'SE', 'SD']).order_by('created')
        for item in manual_selects:
            try:
                dmactions.action_validation(item, item.dmfileset.auto_action)
                return item
            except(DMExceptions.FilesInUse, DMExceptions.FilesMarkedKeep):
                logger.debug("%s Failed action_validation.  Try next fileset" %
                             item.result.resultsName, extra=logid)
            except DMExceptions.BaseInputLinked:
                # want to allow Basecalling Input delete if all results are expired
                related_objs = DMFileStat.objects.filter(
                    result__experiment=item.result.experiment, dmfileset__type=dmactions_types.BASE)
                if related_objs.count() == related_objs.filter(created__lt=threshdate).count():
                    item.allow_delete = True
                    return item
                else:
                    logger.debug("%s Failed action_validation.  Try next fileset" %
                                 item.result.resultsName, extra=logid)
            except:
                logger.error(traceback.format_exc(), extra=logid)
        raise DMExceptions.NoDMFileStat("NONE FOUND")

    try:
        # Create lock file to prevent more than one celery task for manual action (export or archive)
        lock_id = 'manual_action_lock_id'
        logid = {'logid': "%s" % (lock_id)}
        applock = TaskLock(lock_id)

        if not applock.lock():
            logger.info("Currently processing: %s(%s)" % (lock_id, applock.get()), extra=logid)
            return

        logger.debug("lock file created: %s(%s)" % (lock_id, applock.get()), extra=logid)

    except Exception as e:
        logger.error(traceback.format_exc(), extra=logid)

    try:
        #
        # Check for manually selected Archive and Export actions - action_state == 'SA' or 'SE' or 'SD'
        # Manual Delete actions do not get processed here.  Only suspended Delete actions get processed here.
        # These jobs should execute even when auto action is disabled.
        # Note: manual actions will not be executed in the order they are selected, but by age.
        #
        actiondmfilestat = getfirstmanualaction()

        user = actiondmfilestat.user_comment.get('user', 'dm_agent')
        user_comment = actiondmfilestat.user_comment.get('user_comment', 'Manual Action')
        logger.info("Picked: %s" % (actiondmfilestat.result.resultsName), extra=logid)

        dmfileset = actiondmfilestat.dmfileset
        applock.update(actiondmfilestat.result.resultsName)
        if actiondmfilestat.action_state == 'SA':
            logger.info("Manual Archive Action: %s from %s" %
                        (dmfileset.type, actiondmfilestat.result.resultsName), extra=logid)
            archive_action(user, user_comment, actiondmfilestat, lock_id, msg_banner=True)
        elif actiondmfilestat.action_state == 'SE':
            logger.info("Manual Export Action: %s from %s" %
                        (dmfileset.type, actiondmfilestat.result.resultsName), extra=logid)
            export_action(user, user_comment, actiondmfilestat, lock_id, msg_banner=True)
        elif actiondmfilestat.action_state == 'SD':
            logger.info("Delete Action: %s from %s" %
                        (dmfileset.type, actiondmfilestat.result.resultsName), extra=logid)
            delete_action(user, "Continuing delete action after being suspended",
                          actiondmfilestat, lock_id, msg_banner=True)
        else:
            logger.warn("Dev Error: we don't handle this '%s' here" %
                        actiondmfilestat.action_state, extra=logid)

    except DMExceptions.NoDMFileStat:
        applock.unlock()
        logger.debug("Worker PID %d lock_id destroyed on exit %s" % (os.getpid(), lock_id), extra=logid)
    # NOTE: all these exceptions are also handled in manage_data() below.  beaucoup de duplication de code
    except (DMExceptions.FilePermission,
            DMExceptions.InsufficientDiskSpace,
            DMExceptions.MediaNotSet,
            DMExceptions.MediaNotAvailable,
            DMExceptions.FilesInUse) as e:
        applock.unlock()
        message = Message.objects.filter(tags__contains=e.tag)
        if not message:
            Message.error(e.message, tags=e.tag)
            # TODO: TS-6525: This logentry will repeat for an Archive action every 30 seconds until the cause of the exception is fixed.
            # at least, while the message banner is raised, suppress additional Log Entries.
            dmactions.add_eventlog(actiondmfilestat, "%s - %s" %
                                   (dmfileset.type, e.message), username='******')
        # State needs to be Error since we do not know previous state (ie, do NOT
        # set to Local, it might get deleted automatically)
        actiondmfilestat.setactionstate('E')
    except DMExceptions.SrcDirDoesNotExist as e:
        applock.unlock()
        msg = "Src Dir not found: %s. Setting action_state to Deleted" % e.message
        EventLog.objects.add_entry(actiondmfilestat.result, msg, username='******')
        actiondmfilestat.setactionstate('DD')
        logger.info(msg, extra=logid)
    except Exception as e:
        applock.unlock()
        msg = "action error on %s " % actiondmfilestat.result.resultsName
        msg += " Error: %s" % str(e)
        logger.error("%s - %s" % (dmfileset.type, msg), extra=logid)
        logger.error(traceback.format_exc(), extra=logid)
        dmactions.add_eventlog(actiondmfilestat, "%s - %s" % (dmfileset.type, msg), username='******')
        # State needs to be Error since we do not know previous state (ie, do NOT
        # set to Local, it might get deleted automatically)
        actiondmfilestat.setactionstate('E')

    return
Beispiel #3
0
def manage_data(deviceid, dmfileset, pathlist, auto_acknowledge_enabled, auto_action_enabled):
    logid = {'logid': "%s" % ('manage_data')}
    logger.debug("manage_data: %s %s" % (dmfileset['auto_action'], dmfileset['type']), extra=logid)

    def getfirstnotpreserved(dmfilestats, action, threshdate):
        '''QuerySet of DMFileStat objects.  Returns first instance of an object
        with preserve_data set to False and passes the action_validation test'''
        logger.debug("Function: %s()" % sys._getframe().f_code.co_name, extra=logid)
        logger.debug("Looking at %d dmfilestat objects" % dmfilestats.count(), extra=logid)
        for archiveme in dmfilestats:
            if not archiveme.getpreserved():
                try:
                    dmactions.action_validation(archiveme, action)
                    return archiveme
                except(DMExceptions.FilesInUse, DMExceptions.FilesMarkedKeep):
                    logger.debug("%s Failed action_validation.  Try next fileset" %
                                 archiveme.result.resultsName, extra=logid)
                except DMExceptions.BaseInputLinked:
                    # want to allow Basecalling Input delete if all results are expired
                    related_objs = DMFileStat.objects.filter(
                        result__experiment=archiveme.result.experiment, dmfileset__type=dmactions_types.BASE)
                    if related_objs.count() == related_objs.filter(created__lt=threshdate).count():
                        archiveme.allow_delete = True
                        return archiveme
                    else:
                        logger.debug("%s Failed action_validation.  Try next fileset" %
                                     archiveme.result.resultsName, extra=logid)
                except:
                    logger.error(traceback.format_exc(), extra=logid)
            else:
                logger.debug("Skipped a preserved fileset: %s" % archiveme.result.resultsName, extra=logid)

        logger.info("%d filestat objects are preserved." % dmfilestats.count(), extra=logid)
        raise DMExceptions.NoDMFileStat("NONE FOUND")

    try:
        # logger.debug("manage_data lock for %s (%d)" % (dmfileset['type'], os.getpid()), extra = logid)
        # Create lock file to prevent more than one celery task for each process_type and partition
        lock_id = "%s_%s" % (hex(deviceid), slugify(dmfileset['type']))
        logid = {'logid': "%s" % (lock_id)}
        applock = TaskLock(lock_id)

        if not applock.lock():
            logger.info("Currently processing: %s(%s)" % (lock_id, applock.get()), extra=logid)
            return

        logger.debug("lock file created: %s(%s)" % (lock_id, applock.get()), extra=logid)

    except Exception as e:
        logger.error(traceback.format_exc(), extra=logid)

    try:
        #---------------------------------------------------------------------------
        # Database object filtering
        #---------------------------------------------------------------------------
        actiondmfilestat = None
        user_comment = "Auto Action"
        # Order by incrementing pk.  This puts them in chronological order.
        # Select DMFileStat objects of category DMFileSet.type (1/4th of all objects)
        dmfilestats = DMFileStat.objects.filter(dmfileset__type=dmfileset['type']).order_by('created')
        tot_obj = dmfilestats.count()

        # Select objects not yet processed
        dmfilestats = dmfilestats.filter(action_state__in=['L', 'S', 'N', 'A'])
        tot_act = dmfilestats.count()

        # Select objects that are old enough
        threshdate = datetime.now(pytz.UTC) - timedelta(days=dmfileset['auto_trigger_age'])
        dmfilestats = dmfilestats.filter(created__lt=threshdate)
        tot_exp = dmfilestats.count()

        # Select objects stored on the deviceid
        query = Q()
        for path in pathlist:
            if dmfileset['type'] == dmactions_types.SIG:
                query |= Q(result__experiment__expDir__startswith=path)
            # These categories have files in both directory paths.
            elif dmfileset['type'] in [dmactions_types.INTR, dmactions_types.BASE]:
                query |= Q(result__experiment__expDir__startswith=path)
                query |= Q(result__reportstorage__dirPath__startswith=path)
            else:
                query |= Q(result__reportstorage__dirPath__startswith=path)

        dmfilestats = dmfilestats.filter(query)
        tot_onpath = dmfilestats.count()

        # Exclude objects marked 'Keep' upfront to optimize db access
        if dmfileset['type'] == dmactions_types.SIG:
            dmfilestats = dmfilestats.exclude(result__experiment__storage_options="KI")
        else:
            dmfilestats = dmfilestats.exclude(preserve_data=True)
        tot_notpreserved = dmfilestats.count()

        # Compress to single log entry
        logger.info("Total: %d Active: %d Expired: %d On Path: %d Not Preserved: %d" %
                    (tot_obj, tot_act, tot_exp, tot_onpath, tot_notpreserved), extra=logid)

        #---------------------------------------------------------------------------
        # Archive
        #---------------------------------------------------------------------------
        if dmfileset['auto_action'] == 'ARC':
            '''
            Rules:
            1) archive a fileset as soon as age threshold reached, regardless of disk threshold
            2) select oldest fileset
            3) select unprocessed fileset
            4) Archiving does not require 'S' -> 'N' -> 'A' progression before action
            5) Do not include filesets marked 'E' in auto-action - can get stuck on that fileset forever
            '''
            logger.info("Exceed %d days. Eligible to archive: %d" %
                        (dmfileset['auto_trigger_age'], dmfilestats.count()), extra=logid)
            actiondmfilestat = None
            # Bail out if disabled
            if auto_action_enabled != True:
                logger.info("Data management auto-action is disabled.", extra=logid)
                applock.unlock()
                logger.debug("Worker PID %d lock_id destroyed %s" % (os.getpid(), lock_id), extra=logid)
                return

            # Select first object stored on the deviceid
            try:
                actiondmfilestat = getfirstnotpreserved(dmfilestats, dmactions.ARCHIVE, threshdate)
                logger.info("Picked: %s" % (actiondmfilestat.result.resultsName), extra=logid)
            except DMExceptions.NoDMFileStat:
                logger.debug("No filesets to archive on this device", extra=logid)
                applock.unlock()
                logger.debug("Worker PID %d lock_id destroyed %s" % (os.getpid(), lock_id), extra=logid)
            except:
                logger.error(traceback.format_exc(), extra=logid)
                applock.unlock()
                logger.debug("Worker PID %d lock_id destroyed %s" % (os.getpid(), lock_id), extra=logid)
            else:
                applock.update(actiondmfilestat.result.resultsName)
                archive_action('dm_agent', user_comment, actiondmfilestat, lock_id)

        #---------------------------------------------------------------------------
        # Delete
        #---------------------------------------------------------------------------
        elif dmfileset['auto_action'] == 'DEL':
            '''
            Rules: If auto-acknowledge is True:
            promote to Acknowledged and delete when age and disk threshold reached.
            If auto-acknowledge is False:
                If fileset type is SIG:
                    'S' -> 'N' -> 'A' progression
                Else:
                    promote to 'A'
                delete an 'A' fileset
            '''
            logger.info("Exceed %d days. Eligible to delete: %d" %
                        (dmfileset['auto_trigger_age'], dmfilestats.count()), extra=logid)
            if auto_acknowledge_enabled:
                if dmfileset['type'] == dmactions_types.SIG:
                    logger.debug("Sig Proc Input Files auto acknowledge enabled", extra=logid)
                '''
                Do not require 'S' -> 'N' -> 'A' progression before action; mark 'A' and process
                '''
                a_list = dmfilestats.filter(action_state='A')
                if a_list.count() > 0:
                    # there are filesets acknowledged and ready to be deleted.  Covers situation where user has
                    # already acknowledged but recently enabled auto-acknowledge as well.
                    # deleteme = a_list[0]
                    try:
                        actiondmfilestat = getfirstnotpreserved(a_list, dmactions.DELETE, threshdate)
                        logger.info("Picked: %s" % (actiondmfilestat.result.resultsName), extra=logid)
                    except DMExceptions.NoDMFileStat:
                        logger.info("No filesets to delete on this device", extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)
                    except:
                        logger.error(traceback.format_exc(), extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)

                if actiondmfilestat == None:
                    # Select oldest fileset regardless if its 'L','S','N','A'.  This covers situation where user
                    # recently enabled auto-acknowledge
                    try:
                        actiondmfilestat = getfirstnotpreserved(dmfilestats, dmactions.DELETE, threshdate)
                        logger.info("Picked: %s" % (actiondmfilestat.result.resultsName), extra=logid)
                    except DMExceptions.NoDMFileStat:
                        logger.info("No filesets to delete on this device", extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)
                    except:
                        logger.error(traceback.format_exc(), extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)
            else:
                if dmfileset['type'] == dmactions_types.SIG:
                    logger.debug("Sig Proc Input Files auto acknowledge disabled", extra=logid)
                    '''
                    Need to select # of filesets and mark 'S'
                    Need to find 'S' filesets and notify (set to 'N')
                    Set queue length to 5
                    sum(S,N,A) == queue length
                    '''
                    # Get email recipient
                    try:
                        recipient = User.objects.get(username='******').email
                    except:
                        recipient = None

                    # Need to select Experiments to process with appropriate dmfilestats action states.
                    exps = Experiment.objects.exclude(
                        storage_options='KI').exclude(expDir='').order_by('date')
                    l_list = exps.filter(
                        results_set__dmfilestat__in=dmfilestats.filter(action_state='L')).distinct()
                    s_list = exps.filter(
                        results_set__dmfilestat__in=dmfilestats.filter(action_state='S')).distinct()
                    n_list = exps.filter(
                        results_set__dmfilestat__in=dmfilestats.filter(action_state='N')).distinct()
                    a_list = exps.filter(
                        results_set__dmfilestat__in=dmfilestats.filter(action_state='A')).distinct()

                    logger.info("Experiments (Keep=False) L:%d S:%d N:%d A:%d" %
                                (l_list.count(), s_list.count(), n_list.count(), a_list.count()), extra=logid)
                    queue_length = 5
                    to_select = queue_length - (a_list.count() + n_list.count() + s_list.count())
                    if to_select > 0:
                        # Mark to_select number of oldest Experiments, from 'L', to 'S'
                        promoted = dmfilestats.filter(
                            result__experiment__id__in=list(l_list[:to_select].values_list('id', flat=True)))
                        if auto_action_enabled:
                            promoted.update(action_state='S')
                            for dmfilestat in promoted:
                                EventLog.objects.add_entry(
                                    dmfilestat.result, "Signal Processing Input Selected for Deletion", username='******')

                    # Get updated list of Selected items
                    selected = dmfilestats.filter(action_state='S')

                    # Send Selected items to be notified
                    if selected.count() > 0 and auto_action_enabled:
                        logger.debug("notify recipient %s" % (recipient), extra=logid)
                        if notify([dmfilestat.result.resultsName for dmfilestat in selected], recipient):
                            selected.update(action_state='N')
                            for dmfilestat in selected:
                                EventLog.objects.add_entry(
                                    dmfilestat.result, "Notification for Deletion Sent", username='******')

                    try:
                        actiondmfilestat = getfirstnotpreserved(
                            dmfilestats.filter(action_state='A'), dmactions.DELETE, threshdate)
                        logger.info("Picked: %s" % (actiondmfilestat.result.resultsName), extra=logid)
                    except DMExceptions.NoDMFileStat:
                        logger.info("No filesets to delete on this device", extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)
                    except:
                        logger.error(traceback.format_exc(), extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)

                else:
                    try:
                        actiondmfilestat = getfirstnotpreserved(dmfilestats, dmactions.DELETE, threshdate)
                        logger.info("Picked: %s" % (actiondmfilestat.result.resultsName), extra=logid)
                    except DMExceptions.NoDMFileStat:
                        logger.info("No filesets to delete on this device", extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)
                    except:
                        logger.error(traceback.format_exc(), extra=logid)
                        applock.unlock()
                        logger.debug("Worker PID %d lock_id destroyed %s" %
                                     (os.getpid(), lock_id), extra=logid)

            # Bail out if disabled
            if auto_action_enabled != True:
                logger.info("Data management auto-action is disabled.", extra=logid)
                applock.unlock()
                logger.debug("Worker PID %d lock_id destroyed %s" % (os.getpid(), lock_id), extra=logid)
                return

            if actiondmfilestat is not None:
                applock.update(actiondmfilestat.result.resultsName)
                delete_action('dm_agent', user_comment, actiondmfilestat, lock_id,
                              confirmed=getattr(actiondmfilestat, 'allow_delete', False))

        else:
            logger.error("Unknown or unhandled action: %s" % dmfileset['auto_action'], extra=logid)
            applock.unlock()

    except (DMExceptions.FilePermission,
            DMExceptions.InsufficientDiskSpace,
            DMExceptions.MediaNotSet,
            DMExceptions.MediaNotAvailable,
            DMExceptions.FilesInUse) as e:
        applock.unlock()
        message = Message.objects.filter(tags__contains=e.tag)
        if not message:
            Message.error(e.message, tags=e.tag)
            # TODO: TS-6525: This logentry will repeat for an Archive action every 30 seconds until the cause of the exception is fixed.
            # at least, while the message banner is raised, suppress additional Log Entries.
            EventLog.objects.add_entry(actiondmfilestat.result, "%s - %s" %
                                       (dmfileset['type'], e.message), username='******')
    except DMExceptions.SrcDirDoesNotExist as e:
        applock.unlock()
        msg = "Src Dir not found: %s. Setting action_state to Deleted" % e.message
        EventLog.objects.add_entry(actiondmfilestat.result, msg, username='******')
        actiondmfilestat.setactionstate('DD')
        logger.info(msg, extra=logid)
    except Exception as inst:
        applock.unlock()
        msg = ''
        if actiondmfilestat:
            msg = "Auto-action error on %s " % actiondmfilestat.result.resultsName
        msg += " Error: %s" % str(inst)
        logger.error("%s - %s" % (dmfileset['type'], msg), extra=logid)
        logger.error(traceback.format_exc(), extra=logid)

        if actiondmfilestat:
            EventLog.objects.add_entry(actiondmfilestat.result, "%s - %s" %
                                       (dmfileset['type'], msg), username='******')

    return
Beispiel #4
0
def _process_task(pfilename):
    '''
    Recursive celery task.

    To trigger an orphaned task:
    python -c "from iondb.bin import djangoinit; from iondb.rundb.data import dmactions; dmactions._process_task.(<filename>)"
    where <filename> is full path to the data file found in /var/spool/ion
    '''
    logid = {'logid': "%s" % ('dmactions')}
    from datetime import datetime
    from datetime import timedelta
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name, extra=logid)
    logger.debug("Task ID: %s" % _process_task.request.id, extra=logid)

    # catch all unhandled exceptions and clean up
    try:
        try:
            list_of_file_dict = get_action_param_var(pfilename)
        except Exception as e:
            logger.error("Error accessing file: %s.  Cannot continue the DM action!" %
                         (pfilename), extra=logid)
            # parse the filename to extract the dmfilestat pk and retrieve dmfilestat object.
            dmfilestat_pk = os.path.basename(pfilename).split("_")[1]
            dmfilestat = DMFileStat.objects.get(id=dmfilestat_pk)
            raise e

        dmfilestat = DMFileStat.objects.get(id=list_of_file_dict[0]['pk'])
        terminate = True   # flag to indicate recursion termination
        total_processed = 0
        fstatus = "Success"

        start_time = datetime.now()
        max_time_delta = timedelta(seconds=10)

        # list_of_file_dict contains zero, one, or two dictionary variables to iterate over.
        for d_cnt, mydict in enumerate(list_of_file_dict):
            logid = {'logid': "%s" % (mydict.get('lockfile', '_process_task'))}

            # The dictionary contains an element named 'to_process' which is a list variable to iterate over
            logger.debug("%d, start_dir: %s" % (d_cnt, mydict['start_dir']), extra=logid)
            logger.info("%6d %s %s" %
                        (len(mydict['to_process']), dmfilestat.dmfileset.type, dmfilestat.result.resultsName), extra=logid)

            while (datetime.now() - start_time) < max_time_delta:
                # If there are no files left to process, (all to_process lists are empty), the recursion ends
                if len(mydict['to_process']) > 0:
                    terminate = False

                    try:
                        # process one file and remove entry from the list
                        path = mydict['to_process'].pop(0)

                        j = mydict['processed_cnt'] + 1

                        this_file_size = 0
                        if not os.path.islink(path):
                            this_file_size = os.lstat(path)[6]

                        if _process(path, mydict['action'], mydict['archivepath'], mydict['start_dir'], mydict['to_keep']):
                            mydict['processed_cnt'] = j
                            mydict['total_size'] += this_file_size
                            logger.debug("%04d/%04d %s %10d %s" % (
                                j, mydict['total_cnt'], mydict['action'], mydict['total_size'], path), extra=logid)

                    except (OSError, IOError) as e:
                        # IOError: [Errno 28] No space left on device:
                        if e.errno == errno.ENOSPC:
                            raise
                        elif e.errno == errno.ENOENT or e.errno == errno.ESTALE:
                            logger.warn("%04d No longer exists %s" % (j, path), extra=logid)
                            continue
                        else:
                            raise
                    except (DMExceptions.RsyncError, DMExceptions.MediaNotAvailable):
                        raise
                    except:
                        errmsg = "%04d/%04d %s %10d %s" % (
                            j, mydict['total_cnt'], mydict['action'], mydict['total_size'], path)
                        logger.error(errmsg, extra=logid)
                        logger.error(traceback.format_exc(), extra=logid)

                    if not mydict['action'] in [EXPORT, TEST] and dmfilestat.dmfileset.del_empty_dir:
                        thisdir = os.path.dirname(path)
                        try:
                            if len(os.listdir(thisdir)) == 0:
                                if not "plugin_out" in thisdir:
                                    try:
                                        os.rmdir(thisdir)
                                        logger.debug("Removed empty directory: %s" % thisdir, extra=logid)
                                    except Exception as e:
                                        logger.warn("rmdir [%d] %s: %s" % (
                                            e.errno, e.strerror, thisdir), extra=logid)
                        except OSError as e:
                            if e.errno == errno.ENOENT:
                                logger.warn("del_empty_dir Does not exist %s" % (path), extra=logid)
                                continue
                            else:
                                raise e
                else:
                    break

            # only expect to execute this line when no files to process
            total_processed += mydict['total_size']

    except Exception as e:
        fstatus = "Error"
        terminate = True
        dmfilestat.setactionstate('E')
        logger.error("DM Action failure on %s for %s report." %
                     (dmfilestat.dmfileset.type, dmfilestat.result.resultsName), extra=logid)
        logger.error("This %s action will need to be manually completed." % (mydict['action']), extra=logid)
        logger.error("The following is the exception error:\n" + traceback.format_exc(), extra=logid)
        EventLog.objects.add_entry(
            dmfilestat.result, "%s - %s. Action not completed.  User intervention required." % (fstatus, e), username='******')

        # Release the task lock
        try:
            applock = TaskLock(mydict['lockfile'])
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra=logid)

        # Do the user notification
        try:
            # pop up a message banner
            if mydict['msg_banner']:
                dmfileset = dmfilestat.dmfileset
                project_msg = {}
                msg_dict = {}
                msg_dict[dmfileset.type] = fstatus
                project_msg[dmfilestat.result_id] = msg_dict
                project_msg_banner('', project_msg, mydict['action'])
        except:
            logger.error(traceback.format_exc(), extra=logid)

        # ====================================================================
        # Exit function here on error
        # ====================================================================
        return

    # Remove the data file here, no earlier.  In case the task is clobbered, celery
    # will relaunch the task, access the data file and continue the action.
    try:
        os.unlink(pfilename)
    except:
        pass

    if not terminate:
        # ====================================================================
        # Launch next task
        # ====================================================================
        try:
            mydict.get('action', 'unk')
            pfilename = set_action_param_var(list_of_file_dict)
            _process_task.delay(pfilename)
        except:
            logger.error(traceback.format_exc(), extra=logid)

    else:
        # ====================================================================
        # No more files to process.  Clean up and exit.
        # ====================================================================
        try:
            dmfilestat.diskspace = float(total_processed) / (1024 * 1024)
            dmfilestat.save()
            logger.info("%0.1f MB %s processed" %
                        (dmfilestat.diskspace, dmfilestat.dmfileset.type), extra=logid)
            if mydict['action'] in [ARCHIVE, DELETE]:
                _brokenlinks_delete([dmfilestat.result.get_report_dir(), dmfilestat.result.experiment.expDir])
                _emptydir_delete([dmfilestat.result.get_report_dir(), dmfilestat.result.experiment.expDir])
        except:
            logger.error(traceback.format_exc(), extra=logid)

        # Do the user notification
        try:
            _action_complete_update(mydict['user'], mydict['user_comment'], dmfilestat, mydict['action'])

            # pop up a message banner
            if mydict['msg_banner']:
                dmfileset = dmfilestat.dmfileset
                project_msg = {}
                msg_dict = {}
                msg_dict[dmfileset.type] = fstatus
                project_msg[dmfilestat.result_id] = msg_dict
                project_msg_banner(mydict['user'], project_msg, mydict['action'])
        except:
            logger.error(traceback.format_exc(), extra=logid)

        # Release the task lock
        try:
            applock = TaskLock(mydict['lockfile'])
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra=logid)

    return
Beispiel #5
0
def manage_manual_action():
    logger.debug("manage_manual_action")
    try:
        #Create lock file to prevent more than one celery task for manual action (export or archive)
        lock_id = 'manual_action_lock_id'
        applock = TaskLock(lock_id)
        if not (applock.lock()):
            logger.debug("failed to acquire lock file: %d" % os.getpid())
            logger.info("manage_manual_action task still executing")
            return

        logger.debug("Worker PID %d lock_id created %s" %
                     (os.getpid(), lock_id))

    except Exception as e:
        logger.exception(e)

    try:
        #
        # Check for manually selected Archive and Export actions - action_state == 'SA' or 'SE' or 'SD'
        # Manual Delete actions do not get processed here.  Only suspended Delete actions get processed here.
        # These jobs should execute even when auto action is disabled.
        # Note: manual actions will not be executed in the order they are selected, but by age.
        #
        manualSelects = DMFileStat.objects.filter(
            action_state__in=['SA', 'SE', 'SD']).order_by('created')
        if manualSelects.exists():
            actiondmfilestat = manualSelects[0]
            user = actiondmfilestat.user_comment.get('user', 'dm_agent')
            user_comment = actiondmfilestat.user_comment.get(
                'user_comment', 'Manual Action')

            dmfileset = actiondmfilestat.dmfileset
            if actiondmfilestat.action_state == 'SA':
                logger.info(
                    "Manual Archive Action: %s from %s" %
                    (dmfileset.type, actiondmfilestat.result.resultsName))
                archive_action(user,
                               user_comment,
                               actiondmfilestat,
                               lock_id,
                               msg_banner=True)
            elif actiondmfilestat.action_state == 'SE':
                logger.info(
                    "Manual Export Action: %s from %s" %
                    (dmfileset.type, actiondmfilestat.result.resultsName))
                export_action(user,
                              user_comment,
                              actiondmfilestat,
                              lock_id,
                              msg_banner=True)
            elif actiondmfilestat.action_state == 'SD':
                logger.info(
                    "Delete Action: %s from %s" %
                    (dmfileset.type, actiondmfilestat.result.resultsName))
                delete_action(user,
                              "Continuing delete action after being suspended",
                              actiondmfilestat,
                              lock_id,
                              msg_banner=True)
            else:
                logger.warn("Dev Error: we don't handle this '%s' here" %
                            actiondmfilestat.action_state)

        else:
            applock.unlock()
            logger.debug("Worker PID %d lock_id destroyed on exit %s" %
                         (os.getpid(), lock_id))


#NOTE: all these exceptions are also handled in manage_data() below.  beaucoup de duplication de code
    except (DMExceptions.FilePermission, DMExceptions.InsufficientDiskSpace,
            DMExceptions.MediaNotSet, DMExceptions.MediaNotAvailable,
            DMExceptions.FilesInUse) as e:
        applock.unlock()
        message = Message.objects.filter(tags__contains=e.tag)
        if not message:
            Message.error(e.message, tags=e.tag)
            #TODO: TS-6525: This logentry will repeat for an Archive action every 30 seconds until the cause of the exception is fixed.
            #at least, while the message banner is raised, suppress additional Log Entries.
            dmactions.add_eventlog(actiondmfilestat,
                                   "%s - %s" % (dmfileset.type, e.message),
                                   username='******')
        # Revert this dmfilestat object action-state to Local
        actiondmfilestat.setactionstate('L')
    except DMExceptions.SrcDirDoesNotExist as e:
        applock.unlock()
        msg = "Src Dir not found: %s. Setting action_state to Deleted" % e.message
        EventLog.objects.add_entry(actiondmfilestat.result,
                                   msg,
                                   username='******')
        actiondmfilestat.setactionstate('DD')
        logger.info(msg)
    except Exception as e:
        applock.unlock()
        msg = "action error on %s " % actiondmfilestat.result.resultsName
        msg += " Error: %s" % str(e)
        logger.exception("%s - %s" % (dmfileset.type, msg))
        dmactions.add_eventlog(actiondmfilestat,
                               "%s - %s" % (dmfileset.type, msg),
                               username='******')
        # Revert this dmfilestat object action-state to Local
        actiondmfilestat.setactionstate('L')

    return
Beispiel #6
0
def _process_fileset_task(dmfilestat, action, user, user_comment, lockfile, msg_banner):
    '''
    This function generates a list of files to process, then hands the list to a recursive
    celery task function.  The recursion continues until the list is empty.  The calling
    function exits immediately.
    '''
    logid = {'logid':"%s" % (lockfile)}
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name, extra = logid)

    if dmfilestat.isdeleted():
        errmsg = "The %s for %s are deleted" % (dmfilestat.dmfileset.type, dmfilestat.result.resultsName)
        logger.warn(errmsg, extra = logid)
        raise Exception(errmsg)
    elif dmfilestat.isarchived():
        if not os.path.exists(dmfilestat.archivepath):
            errmsg = "Cannot access backup location %s" % dmfilestat.archivepath
            logger.warn(errmsg, extra = logid)
            raise Exception(errmsg)
        else:
            # search archived directory
            search_dirs = [dmfilestat.archivepath]
    else:
        # search both results directory and raw data directory
        search_dirs = [dmfilestat.result.get_report_dir(), dmfilestat.result.experiment.expDir]

    # Create a lock file here to block any other actions on this report (see TS-8411)
    lock_id = "%s_%s" % (dmfilestat.result.resultsName, dm_utils.slugify(dmfilestat.dmfileset.type))
    locallock = TaskLock(lock_id, timeout=60) # short timeout in case lock release code doesn't get called

    if not(locallock.lock()):
        logger.warn("lock file exists: %s(%s)" % (lock_id, locallock.get()), extra = logid)
        # Release the task lock
        try:
            applock = TaskLock(lockfile)
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra = logid)
        return

    logger.info("lock file created: %s(%s)" % (lock_id, locallock.get()), extra = logid)

    if action == ARCHIVE:
        dmfilestat.setactionstate('AG')
    elif action == DELETE:
        dmfilestat.setactionstate('DG')
    elif action == EXPORT:
        dmfilestat.setactionstate('EG')

    # List of all files associated with the report
    cached_file_list = dm_utils.get_walk_filelist(search_dirs, list_dir=dmfilestat.result.get_report_dir())

    #Determine if this file type is eligible to use a keep list
    kpatterns = _get_keeper_list(dmfilestat, action)

    #Create a list of files eligible to process
    list_of_file_dict = []
    is_thumbnail = dmfilestat.result.isThumbnail
    add_linked_sigproc = False if (action == DELETE or dmfilestat.dmfileset.type == dmactions_types.INTR) else True
    for start_dir in search_dirs:
        logger.debug("Searching: %s" % start_dir, extra = logid)
        to_process = []
        to_keep = []
        if os.path.isdir(start_dir):
            to_process, to_keep = dm_utils._file_selector(start_dir,
                                                 dmfilestat.dmfileset.include,
                                                 dmfilestat.dmfileset.exclude,
                                                 kpatterns,
                                                 is_thumbnail,
                                                 add_linked_sigproc,
                                                 cached=cached_file_list)
        logger.info("%d files to process at %s" % (len(list(set(to_process) - set(to_keep))), start_dir), extra = logid)
        list_of_file_dict.append(
            {
                'pk':dmfilestat.id,
                'action':action,
                'archivepath':dmfilestat.archivepath,
                'start_dir':start_dir,
                'to_process':to_process,
                'to_keep':to_keep,
                'total_cnt':len(list(set(to_process) - set(to_keep))),
                'processed_cnt':0,
                'total_size':0,
                'user':user,
                'user_comment':user_comment,
                'lockfile':lockfile,
                'msg_banner':msg_banner,
            }
        )

    try:
        pfilename = set_action_param_var(list_of_file_dict)

        # Call the recursive celery task function to process the list
        _process_task.delay(pfilename)
            
    except:
        logger.error("We got an error here, _process_fileset_task", extra = logid)
        raise
    finally:
        if locallock:
            locallock.unlock()

    return
Beispiel #7
0
def _process_task(pfilename):
    '''
    Recursive celery task
    '''
    from datetime import datetime
    from datetime import timedelta
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name)
    logger.debug("Task ID: %s" % _process_task.request.id)


    #catch all unhandled exceptions and clean up
    try:
        list_of_file_dict = get_action_param_file(pfilename)
        os.unlink(pfilename)

        dmfilestat = DMFileStat.objects.get(id=list_of_file_dict[0]['pk'])
        terminate = True   # flag to indicate recursion termination
        total_processed = 0

        start_time = datetime.now()
        max_time_delta = timedelta(seconds=10)

        # list_of_file_dict contains zero, one, or two dictionary variables to iterate over.
        for q,dict in enumerate(list_of_file_dict):
            # The dictionary contains an element named 'to_process' which is a list variable to iterate over
            logger.debug("%d, start_dir: %s" % (q,dict['start_dir']))

            while (datetime.now() - start_time) < max_time_delta:
                # If there are no files left to process, (all to_process lists are empty), the recursion ends
                if len(dict['to_process']) > 0:
                    terminate = False

                    try:
                        # process one file and remove entry from the list
                        path = dict['to_process'].pop(0)

                        j = dict['processed_cnt'] + 1

                        this_file_size = 0
                        if not os.path.islink(path):
                            this_file_size = os.lstat(path)[6]

                        if _process(path, dict['action'], dict['archivepath'], dict['start_dir'], dict['to_keep']):
                            dict['processed_cnt'] = j
                            dict['total_size'] += this_file_size
                            logger.info("%04d/%04d %s %10d %s" % (j, dict['total_cnt'], dict['action'], dict['total_size'], path))

                    except (OSError,IOError) as e:
                        #IOError: [Errno 28] No space left on device:
                        if e.errno == errno.ENOSPC:
                            raise
                        elif e.errno == errno.ENOENT:
                            logger.warn("%04d No longer exists %s" % (j,path))
                            continue
                    except:
                        errmsg = "%04d/%04d %s %10d %s" % (j, dict['total_cnt'], dict['action'], dict['total_size'], path)
                        logger.error(errmsg)
                        logger.error(traceback.format_exc())

                    if not dict['action'] in [EXPORT,TEST] and dmfilestat.dmfileset.del_empty_dir:
                        dir = os.path.dirname(path)
                        try:
                            if len(os.listdir(dir)) == 0:
                                if not "plugin_out" in dir:
                                    try:
                                        os.rmdir(dir)
                                        logger.debug("Removed empty directory: %s" % dir)
                                    except Exception as e:
                                        logger.warn("rmdir [%d] %s: %s" % (e.errno,e.strerror,dir))
                        except OSError as e:
                            if e.errno == errno.ENOENT:
                                logger.warn("del_empty_dir Does not exist %s" % (path))
                                continue
                            else:
                                raise e
                else:
                    break

            # only expect to execute this line when no files to process
            total_processed += dict['total_size']
    except:
        dmfilestat.setactionstate('E')
        logger.error("DM Action failure on %s for %s report." % (dmfilestat.dmfileset.type,dmfilestat.result.resultsName))
        logger.error("This %s action will need to be manually completed." % (dict['action']))
        logger.error("The following is the exception error:\n"+traceback.format_exc())
        EventLog.objects.add_entry(dmfilestat.result,"%s - %s" % (dmfilestat.dmfileset.type, msg),username='******')
        if dict['lockfile']:
            applock = TaskLock(dict['lockfile'])
            applock.unlock()
        return

    #logger.debug("Sleep for 1")
    #import time
    #time.sleep(1)
    if terminate:
        try:
            # No more files to process.  Do the clean up.
            dmfilestat.diskspace = float(total_processed)/(1024*1024)
            dmfilestat.save()
            logger.info("%0.1f MB %s processed" % (dmfilestat.diskspace, dmfilestat.dmfileset.type))
            if dict['action'] in [ARCHIVE, DELETE]:
                _emptydir_delete(dmfilestat)

            _action_complete_update(dict['user'], dict['user_comment'], dmfilestat, dict['action'])

            # pop up a message banner
            if dict['msg_banner']:
                dmfileset = dmfilestat.dmfileset
                project_msg = {}
                msg_dict = {}
                msg_dict[dmfileset.type] = "Success"
                project_msg[dmfilestat.result_id] = msg_dict
                project_msg_banner('', project_msg, dict['action'])

            if dict['lockfile']:
                applock = TaskLock(dict['lockfile'])
                applock.unlock()
        except:
            logger.exception(traceback.format_exc())
    else:
        # Launch next task
        try:
            pfilename = set_action_param_file(list_of_file_dict)
            celery_result = _process_task.delay(pfilename)
        except:
            logger.error(traceback.format_exc())

    return
Beispiel #8
0
def _process_task(pfilename):
    '''
    Recursive celery task
    '''
    from datetime import datetime
    from datetime import timedelta
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name)
    logger.debug("Task ID: %s" % _process_task.request.id)

    #catch all unhandled exceptions and clean up
    try:
        list_of_file_dict = get_action_param_file(pfilename)
        os.unlink(pfilename)

        dmfilestat = DMFileStat.objects.get(id=list_of_file_dict[0]['pk'])
        terminate = True  # flag to indicate recursion termination
        total_processed = 0

        start_time = datetime.now()
        max_time_delta = timedelta(seconds=10)

        # list_of_file_dict contains zero, one, or two dictionary variables to iterate over.
        for q, dict in enumerate(list_of_file_dict):
            # The dictionary contains an element named 'to_process' which is a list variable to iterate over
            logger.debug("%d, start_dir: %s" % (q, dict['start_dir']))

            while (datetime.now() - start_time) < max_time_delta:
                # If there are no files left to process, (all to_process lists are empty), the recursion ends
                if len(dict['to_process']) > 0:
                    terminate = False

                    try:
                        # process one file and remove entry from the list
                        path = dict['to_process'].pop(0)

                        j = dict['processed_cnt'] + 1

                        this_file_size = 0
                        if not os.path.islink(path):
                            this_file_size = os.lstat(path)[6]

                        if _process(path, dict['action'], dict['archivepath'],
                                    dict['start_dir'], dict['to_keep']):
                            dict['processed_cnt'] = j
                            dict['total_size'] += this_file_size
                            logger.info("%04d/%04d %s %10d %s" %
                                        (j, dict['total_cnt'], dict['action'],
                                         dict['total_size'], path))

                    except (OSError, IOError) as e:
                        #IOError: [Errno 28] No space left on device:
                        if e.errno == errno.ENOSPC:
                            raise
                        elif e.errno == errno.ENOENT:
                            logger.warn("%04d No longer exists %s" % (j, path))
                            continue
                    except:
                        errmsg = "%04d/%04d %s %10d %s" % (
                            j, dict['total_cnt'], dict['action'],
                            dict['total_size'], path)
                        logger.error(errmsg)
                        logger.error(traceback.format_exc())

                    if not dict['action'] in [
                            EXPORT, TEST
                    ] and dmfilestat.dmfileset.del_empty_dir:
                        dir = os.path.dirname(path)
                        try:
                            if len(os.listdir(dir)) == 0:
                                if not "plugin_out" in dir:
                                    try:
                                        os.rmdir(dir)
                                        logger.debug(
                                            "Removed empty directory: %s" %
                                            dir)
                                    except Exception as e:
                                        logger.warn("rmdir [%d] %s: %s" %
                                                    (e.errno, e.strerror, dir))
                        except OSError as e:
                            if e.errno == errno.ENOENT:
                                logger.warn("del_empty_dir Does not exist %s" %
                                            (path))
                                continue
                            else:
                                raise e
                else:
                    break

            # only expect to execute this line when no files to process
            total_processed += dict['total_size']
    except:
        dmfilestat.setactionstate('E')
        logger.error(
            "DM Action failure on %s for %s report." %
            (dmfilestat.dmfileset.type, dmfilestat.result.resultsName))
        logger.error("This %s action will need to be manually completed." %
                     (dict['action']))
        logger.error("The following is the exception error:\n" +
                     traceback.format_exc())
        EventLog.objects.add_entry(dmfilestat.result,
                                   "%s - %s" %
                                   (dmfilestat.dmfileset.type, msg),
                                   username='******')
        if dict['lockfile']:
            applock = TaskLock(dict['lockfile'])
            applock.unlock()
        return

    #logger.debug("Sleep for 1")
    #import time
    #time.sleep(1)
    if terminate:
        try:
            # No more files to process.  Do the clean up.
            dmfilestat.diskspace = float(total_processed) / (1024 * 1024)
            dmfilestat.save()
            logger.info("%0.1f MB %s processed" %
                        (dmfilestat.diskspace, dmfilestat.dmfileset.type))
            if dict['action'] in [ARCHIVE, DELETE]:
                _emptydir_delete(dmfilestat)

            _action_complete_update(dict['user'], dict['user_comment'],
                                    dmfilestat, dict['action'])

            # pop up a message banner
            if dict['msg_banner']:
                dmfileset = dmfilestat.dmfileset
                project_msg = {}
                msg_dict = {}
                msg_dict[dmfileset.type] = "Success"
                project_msg[dmfilestat.result_id] = msg_dict
                project_msg_banner('', project_msg, dict['action'])

            if dict['lockfile']:
                applock = TaskLock(dict['lockfile'])
                applock.unlock()
        except:
            logger.exception(traceback.format_exc())
    else:
        # Launch next task
        try:
            pfilename = set_action_param_file(list_of_file_dict)
            celery_result = _process_task.delay(pfilename)
        except:
            logger.error(traceback.format_exc())

    return
Beispiel #9
0
def manage_manual_action():
    logger.debug("manage_manual_action", extra = {'logid':"%s" % ('manual_action')})
    try:
        #Create lock file to prevent more than one celery task for manual action (export or archive)
        lock_id = 'manual_action_lock_id'
        d = {'logid':"%s" % (lock_id)}
        applock = TaskLock(lock_id)

        if not(applock.lock()):
            logger.debug("lock file exists: %s(%s)" % (lock_id, applock.get()), extra = d)
            return

        logger.debug("lock file created: %s(%s)" % (lock_id, applock.get()), extra = d)

    except Exception as e:
        logger.error(traceback.format_exc(), extra = d)


    try:
        #
        # Check for manually selected Archive and Export actions - action_state == 'SA' or 'SE' or 'SD'
        # Manual Delete actions do not get processed here.  Only suspended Delete actions get processed here.
        # These jobs should execute even when auto action is disabled.
        # Note: manual actions will not be executed in the order they are selected, but by age.
        #
        manualSelects = DMFileStat.objects.filter(action_state__in=['SA','SE','SD']).order_by('created')
        if manualSelects.exists():
            actiondmfilestat = manualSelects[0]
            user = actiondmfilestat.user_comment.get('user', 'dm_agent')
            user_comment = actiondmfilestat.user_comment.get('user_comment', 'Manual Action')

            dmfileset = actiondmfilestat.dmfileset
            applock.update(actiondmfilestat.result.resultsName)
            if actiondmfilestat.action_state == 'SA':
                logger.info("Manual Archive Action: %s from %s" % (dmfileset.type,actiondmfilestat.result.resultsName), extra = d)
                archive_action(user, user_comment, actiondmfilestat, lock_id, msg_banner = True)
            elif actiondmfilestat.action_state == 'SE':
                logger.info("Manual Export Action: %s from %s" % (dmfileset.type,actiondmfilestat.result.resultsName), extra = d)
                export_action(user, user_comment, actiondmfilestat, lock_id, msg_banner = True)
            elif actiondmfilestat.action_state == 'SD':
                logger.info("Delete Action: %s from %s" % (dmfileset.type,actiondmfilestat.result.resultsName), extra = d)
                delete_action(user, "Continuing delete action after being suspended", actiondmfilestat, lock_id, msg_banner = True)
            else:
                logger.warn("Dev Error: we don't handle this '%s' here" % actiondmfilestat.action_state, extra = d)

        else:
            applock.unlock()
            logger.debug("Worker PID %d lock_id destroyed on exit %s" % (os.getpid(),lock_id), extra = d)
#NOTE: all these exceptions are also handled in manage_data() below.  beaucoup de duplication de code
    except (DMExceptions.FilePermission,
            DMExceptions.InsufficientDiskSpace,
            DMExceptions.MediaNotSet,
            DMExceptions.MediaNotAvailable,
            DMExceptions.FilesInUse) as e:
        applock.unlock()
        message  = Message.objects.filter(tags__contains=e.tag)
        if not message:
            Message.error(e.message,tags=e.tag)
            #TODO: TS-6525: This logentry will repeat for an Archive action every 30 seconds until the cause of the exception is fixed.
            #at least, while the message banner is raised, suppress additional Log Entries.
            dmactions.add_eventlog(actiondmfilestat, "%s - %s" % (dmfileset.type, e.message), username='******')
        # Revert this dmfilestat object action-state to Local
        actiondmfilestat.setactionstate('L')
    except DMExceptions.SrcDirDoesNotExist as e:
        applock.unlock()
        msg = "Src Dir not found: %s. Setting action_state to Deleted" % e.message
        EventLog.objects.add_entry(actiondmfilestat.result,msg,username='******')
        actiondmfilestat.setactionstate('DD')
        logger.info(msg, extra = d)
    except Exception as e:
        applock.unlock()
        msg = "action error on %s " % actiondmfilestat.result.resultsName
        msg += " Error: %s" % str(e)
        logger.error("%s - %s" % (dmfileset.type, msg), extra = d)
        logger.error(traceback.format_exc(), extra = d)
        dmactions.add_eventlog(actiondmfilestat,"%s - %s" % (dmfileset.type, msg),username='******')
        # Revert this dmfilestat object action-state to Local
        actiondmfilestat.setactionstate('L')

    return
Beispiel #10
0
def _process_task(pfilename):
    '''
    Recursive celery task.

    To trigger an orphaned task:
    python -c "from iondb.bin import djangoinit; from iondb.rundb.data import dmactions; dmactions._process_task.(<filename>)"
    where <filename> is full path to the data file found in /var/spool/ion
    '''
    logid = {'logid':"%s" % ('dmactions')}
    from datetime import datetime
    from datetime import timedelta
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name, extra = logid)
    logger.debug("Task ID: %s" % _process_task.request.id, extra = logid)

    #catch all unhandled exceptions and clean up
    try:
        try:
            list_of_file_dict = get_action_param_var(pfilename)
        except Exception as e:
            logger.error("Error accessing file: %s.  Cannot continue the DM action!" % (pfilename), extra = logid)
            # parse the filename to extract the dmfilestat pk and retrieve dmfilestat object.
            dmfilestat_pk = os.path.basename(pfilename).split("_")[1]
            dmfilestat = DMFileStat.objects.get(id=dmfilestat_pk)
            raise e

        dmfilestat = DMFileStat.objects.get(id=list_of_file_dict[0]['pk'])
        terminate = True   # flag to indicate recursion termination
        total_processed = 0
        fstatus = "Success"

        start_time = datetime.now()
        max_time_delta = timedelta(seconds=10)

        # list_of_file_dict contains zero, one, or two dictionary variables to iterate over.
        for d_cnt, dict in enumerate(list_of_file_dict):
            logid = {'logid':"%s" % (dict.get('lockfile','_process_task'))}

            # The dictionary contains an element named 'to_process' which is a list variable to iterate over
            logger.debug("%d, start_dir: %s" % (d_cnt, dict['start_dir']), extra = logid)
            logger.info("%6d %s %s" %(len(dict['to_process']), dmfilestat.dmfileset.type, dmfilestat.result.resultsName), extra = logid)

            while (datetime.now() - start_time) < max_time_delta:
                # If there are no files left to process, (all to_process lists are empty), the recursion ends
                if len(dict['to_process']) > 0:
                    terminate = False

                    try:
                        # process one file and remove entry from the list
                        path = dict['to_process'].pop(0)

                        j = dict['processed_cnt'] + 1

                        this_file_size = 0
                        if not os.path.islink(path):
                            this_file_size = os.lstat(path)[6]

                        if _process(path, dict['action'], dict['archivepath'], dict['start_dir'], dict['to_keep']):
                            dict['processed_cnt'] = j
                            dict['total_size'] += this_file_size
                            logger.debug("%04d/%04d %s %10d %s" % (j, dict['total_cnt'], dict['action'], dict['total_size'], path), extra = logid)

                    except (OSError, IOError) as e:
                        #IOError: [Errno 28] No space left on device:
                        if e.errno == errno.ENOSPC:
                            raise
                        elif e.errno == errno.ENOENT or e.errno == errno.ESTALE:
                            logger.warn("%04d No longer exists %s" % (j, path), extra = logid)
                            continue
                        else:
                            raise
                    except (DMExceptions.RsyncError, DMExceptions.MediaNotAvailable):
                        raise
                    except:
                        errmsg = "%04d/%04d %s %10d %s" % (j, dict['total_cnt'], dict['action'], dict['total_size'], path)
                        logger.error(errmsg, extra = logid)
                        logger.error(traceback.format_exc(), extra = logid)

                    if not dict['action'] in [EXPORT, TEST] and dmfilestat.dmfileset.del_empty_dir:
                        dir = os.path.dirname(path)
                        try:
                            if len(os.listdir(dir)) == 0:
                                if not "plugin_out" in dir:
                                    try:
                                        os.rmdir(dir)
                                        logger.debug("Removed empty directory: %s" % dir, extra = logid)
                                    except Exception as e:
                                        logger.warn("rmdir [%d] %s: %s" % (e.errno, e.strerror, dir), extra = logid)
                        except OSError as e:
                            if e.errno == errno.ENOENT:
                                logger.warn("del_empty_dir Does not exist %s" % (path), extra = logid)
                                continue
                            else:
                                raise e
                else:
                    break

            # only expect to execute this line when no files to process
            total_processed += dict['total_size']

    except Exception as e:
        fstatus = "Error"
        terminate = True
        dmfilestat.setactionstate('E')
        logger.error("DM Action failure on %s for %s report." % (dmfilestat.dmfileset.type, dmfilestat.result.resultsName), extra = logid)
        logger.error("This %s action will need to be manually completed." % (dict['action']), extra = logid)
        logger.error("The following is the exception error:\n"+traceback.format_exc(), extra = logid)
        EventLog.objects.add_entry(dmfilestat.result,"%s - %s. Action not completed.  User intervention required." % (fstatus, e), username='******')

        # Release the task lock
        try:
            applock = TaskLock(dict['lockfile'])
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra = logid)

        # Do the user notification
        try:
            # pop up a message banner
            if dict['msg_banner']:
                dmfileset = dmfilestat.dmfileset
                project_msg = {}
                msg_dict = {}
                msg_dict[dmfileset.type] = fstatus
                project_msg[dmfilestat.result_id] = msg_dict
                project_msg_banner('', project_msg, dict['action'])
        except:
            logger.error(traceback.format_exc(), extra = logid)

        # ====================================================================
        # Exit function here on error
        # ====================================================================
        return

    # Remove the data file here, no earlier.  In case the task is clobbered, celery
    # will relaunch the task, access the data file and continue the action.
    try:
        os.unlink(pfilename)
    except:
        pass


    if not terminate:
        # ====================================================================
        # Launch next task
        # ====================================================================
        try:
            dict.get('action','unk')
            pfilename = set_action_param_var(list_of_file_dict)
            _process_task.delay(pfilename)
        except:
            logger.error(traceback.format_exc(), extra = logid)

    else:
        # ====================================================================
        # No more files to process.  Clean up and exit.
        # ====================================================================
        try:
            dmfilestat.diskspace = float(total_processed)/(1024*1024)
            dmfilestat.save()
            logger.info("%0.1f MB %s processed" % (dmfilestat.diskspace, dmfilestat.dmfileset.type), extra = logid)
            if dict['action'] in [ARCHIVE, DELETE]:
                _brokenlinks_delete([dmfilestat.result.get_report_dir(), dmfilestat.result.experiment.expDir])
                _emptydir_delete([dmfilestat.result.get_report_dir(), dmfilestat.result.experiment.expDir])
        except:
            logger.error(traceback.format_exc(), extra = logid)

        # Do the user notification
        try:
            _action_complete_update(dict['user'], dict['user_comment'], dmfilestat, dict['action'])

            # pop up a message banner
            if dict['msg_banner']:
                dmfileset = dmfilestat.dmfileset
                project_msg = {}
                msg_dict = {}
                msg_dict[dmfileset.type] = fstatus
                project_msg[dmfilestat.result_id] = msg_dict
                project_msg_banner(dict['user'], project_msg, dict['action'])
        except:
            logger.error(traceback.format_exc(), extra = logid)

        # Release the task lock
        try:
            applock = TaskLock(dict['lockfile'])
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra = logid)

    return
Beispiel #11
0
def _process_fileset_task(dmfilestat, action, user, user_comment, lockfile, msg_banner):
    '''
    This function generates a list of files to process, then hands the list to a recursive
    celery task function.  The recursion continues until the list is empty.  The calling
    function exits immediately.
    '''
    logid = {'logid':"%s" % (lockfile)}
    logger.debug("Function: %s()" % sys._getframe().f_code.co_name, extra = logid)

    if dmfilestat.isdeleted():
        errmsg = "The %s for %s are deleted" % (dmfilestat.dmfileset.type, dmfilestat.result.resultsName)
        logger.warn(errmsg, extra = logid)
        raise Exception(errmsg)
    elif dmfilestat.isarchived():
        if not os.path.exists(dmfilestat.archivepath):
            errmsg = "Cannot access backup location %s" % dmfilestat.archivepath
            logger.warn(errmsg, extra = logid)
            raise Exception(errmsg)
        else:
            # search archived directory
            search_dirs = [dmfilestat.archivepath]
    else:
        # search both results directory and raw data directory
        search_dirs = [dmfilestat.result.get_report_dir(), dmfilestat.result.experiment.expDir]

    # Create a lock file here to block any other actions on this report (see TS-8411)
    lock_id = "%s_%s" % (dmfilestat.result.resultsName, dm_utils.slugify(dmfilestat.dmfileset.type))
    locallock = TaskLock(lock_id, timeout=60) # short timeout in case lock release code doesn't get called

    if not(locallock.lock()):
        logger.warn("lock file exists: %s(%s)" % (lock_id, locallock.get()), extra = logid)
        # Release the task lock
        try:
            applock = TaskLock(lockfile)
            applock.unlock()
        except:
            logger.error(traceback.format_exc(), extra = logid)
        return

    logger.info("lock file created: %s(%s)" % (lock_id, locallock.get()), extra = logid)

    if action == ARCHIVE:
        dmfilestat.setactionstate('AG')
    elif action == DELETE:
        dmfilestat.setactionstate('DG')
    elif action == EXPORT:
        dmfilestat.setactionstate('EG')

    # List of all files associated with the report
    cached_file_list = dm_utils.get_walk_filelist(search_dirs, list_dir=dmfilestat.result.get_report_dir())

    #Determine if this file type is eligible to use a keep list
    kpatterns = _get_keeper_list(dmfilestat, action)

    #Create a list of files eligible to process
    list_of_file_dict = []
    is_thumbnail = dmfilestat.result.isThumbnail
    add_linked_sigproc = False if (action == DELETE or dmfilestat.dmfileset.type == dmactions_types.INTR) else True
    for start_dir in search_dirs:
        logger.debug("Searching: %s" % start_dir, extra = logid)
        to_process = []
        to_keep = []
        if os.path.isdir(start_dir):
            to_process, to_keep = dm_utils._file_selector(start_dir,
                                                 dmfilestat.dmfileset.include,
                                                 dmfilestat.dmfileset.exclude,
                                                 kpatterns,
                                                 is_thumbnail,
                                                 add_linked_sigproc,
                                                 cached=cached_file_list)
        logger.info("%d files to process at %s" % (len(list(set(to_process) - set(to_keep))), start_dir), extra = logid)
        list_of_file_dict.append(
            {
                'pk':dmfilestat.id,
                'action':action,
                'archivepath':dmfilestat.archivepath,
                'start_dir':start_dir,
                'to_process':to_process,
                'to_keep':to_keep,
                'total_cnt':len(list(set(to_process) - set(to_keep))),
                'processed_cnt':0,
                'total_size':0,
                'user':user,
                'user_comment':user_comment,
                'lockfile':lockfile,
                'msg_banner':msg_banner,
            }
        )

    try:
        pfilename = set_action_param_var(list_of_file_dict)

        # Call the recursive celery task function to process the list
        _process_task.delay(pfilename)
            
    except:
        logger.error("We got an error here, _process_fileset_task", extra = logid)
        raise
    finally:
        if locallock:
            locallock.unlock()

    return