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