def receiver(id, total_threads=1, full_mode=False):
"""
Main loop to consume messages from the FTS3 producer.
"""
logging.info('receiver starting in full mode: %s' % full_mode)
executable = 'conveyor-receiver'
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
# Make an initial heartbeat so that all finishers have the correct worker number on the next try
heartbeat.live(executable, hostname, pid, hb_thread)
brokers_alias = []
brokers_resolved = []
try:
brokers_alias = [
b.strip()
for b in config_get('messaging-fts3', 'brokers').split(',')
]
except Exception:
raise Exception('Could not load brokers from configuration')
logging.info('resolving broker dns alias: %s' % brokers_alias)
brokers_resolved = []
for broker in brokers_alias:
addrinfos = socket.getaddrinfo(broker, 0, socket.AF_INET, 0,
socket.IPPROTO_TCP)
brokers_resolved.extend(ai[4][0] for ai in addrinfos)
logging.info('brokers resolved to %s', brokers_resolved)
logging.info('checking authentication method')
use_ssl = True
try:
use_ssl = config_get_bool('messaging-fts3', 'use_ssl')
except:
logging.info(
'could not find use_ssl in configuration -- please update your rucio.cfg'
)
port = config_get_int('messaging-fts3', 'port')
vhost = config_get('messaging-fts3',
'broker_virtual_host',
raise_exception=False)
if not use_ssl:
username = config_get('messaging-fts3', 'username')
password = config_get('messaging-fts3', 'password')
port = config_get_int('messaging-fts3', 'nonssl_port')
conns = []
for broker in brokers_resolved:
if not use_ssl:
logging.info('setting up username/password authentication: %s' %
broker)
con = stomp.Connection12(host_and_ports=[(broker, port)],
use_ssl=False,
vhost=vhost,
reconnect_attempts_max=999)
else:
logging.info('setting up ssl cert/key authentication: %s' % broker)
con = stomp.Connection12(
host_and_ports=[(broker, port)],
use_ssl=True,
ssl_key_file=config_get('messaging-fts3', 'ssl_key_file'),
ssl_cert_file=config_get('messaging-fts3', 'ssl_cert_file'),
vhost=vhost,
reconnect_attempts_max=999)
conns.append(con)
logging.info('receiver started')
while not graceful_stop.is_set():
heartbeat.live(executable, hostname, pid, hb_thread)
for conn in conns:
if not conn.is_connected():
logging.info('connecting to %s' %
conn.transport._Transport__host_and_ports[0][0])
record_counter('daemons.messaging.fts3.reconnect.%s' %
conn.transport._Transport__host_and_ports[0]
[0].split('.')[0])
conn.set_listener(
'rucio-messaging-fts3',
Receiver(
broker=conn.transport._Transport__host_and_ports[0],
id=id,
total_threads=total_threads,
full_mode=full_mode))
if not use_ssl:
conn.connect(username, password, wait=True)
else:
conn.connect(wait=True)
conn.subscribe(destination=config_get('messaging-fts3',
'destination'),
id='rucio-messaging-fts3',
ack='auto')
time.sleep(1)
logging.info('receiver graceful stop requested')
for conn in conns:
try:
conn.disconnect()
except Exception:
pass
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('receiver graceful stop done')
def transmogrifier(bulk=5, once=False, sleep_time=60):
"""
Creates a Transmogrifier Worker that gets a list of new DIDs for a given hash,
identifies the subscriptions matching the DIDs and
submit a replication rule for each DID matching a subscription.
:param thread: Thread number at startup.
:param bulk: The number of requests to process.
:param once: Run only once.
:param sleep_time: Time between two cycles.
"""
executable = ' '.join(argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
while not graceful_stop.is_set():
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
dids, subscriptions = [], []
tottime = 0
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'], heart_beat['nr_threads'])
try:
# Get the new DIDs based on the is_new flag
for did in list_new_dids(thread=heart_beat['assign_thread'], total_threads=heart_beat['nr_threads'], chunk_size=bulk, did_type=None):
dids.append({'scope': did['scope'], 'did_type': str(did['did_type']), 'name': did['name']})
sub_dict = {3: []}
# Get the list of subscriptions. The default priority of the subscription is 3. 0 is the highest priority, 5 the lowest
# The priority is defined as 'policyid'
for sub in list_subscriptions(None, None):
if sub['state'] != SubscriptionState.INACTIVE and sub['lifetime'] and (datetime.now() > sub['lifetime']):
update_subscription(name=sub['name'], account=sub['account'], metadata={'state': SubscriptionState.INACTIVE})
elif sub['state'] in [SubscriptionState.ACTIVE, SubscriptionState.UPDATED]:
priority = 3
if 'policyid' in sub:
if int(sub['policyid']) not in sub_dict:
sub_dict[int(sub['policyid'])] = []
priority = int(sub['policyid'])
sub_dict[priority].append(sub)
priorities = list(sub_dict.keys())
priorities.sort()
# Order the subscriptions according to their priority
for priority in priorities:
subscriptions.extend(sub_dict[priority])
except SubscriptionNotFound as error:
logging.warning(prepend_str + 'No subscriptions defined: %s' % (str(error)))
time.sleep(10)
continue
except Exception as error:
logging.error(prepend_str + 'Failed to get list of new DIDs or subscriptions: %s' % (str(error)))
try:
results = {}
start_time = time.time()
blacklisted_rse_id = [rse['id'] for rse in list_rses({'availability_write': False})]
logging.debug(prepend_str + 'In transmogrifier worker')
identifiers = []
# Loop over all the new dids
for did in dids:
did_success = True
if did['did_type'] == str(DIDType.DATASET) or did['did_type'] == str(DIDType.CONTAINER):
did_tag = '%s:%s' % (did['scope'].internal, did['name'])
results[did_tag] = []
try:
metadata = get_metadata(did['scope'], did['name'])
# Loop over all the subscriptions
for subscription in subscriptions:
# Check if the DID match the subscription
if is_matching_subscription(subscription, did, metadata) is True:
filter_string = loads(subscription['filter'])
split_rule = filter_string.get('split_rule', False)
stime = time.time()
results[did_tag].append(subscription['id'])
logging.info(prepend_str + '%s:%s matches subscription %s' % (did['scope'], did['name'], subscription['name']))
rules = loads(subscription['replication_rules'])
created_rules = {}
cnt = 0
for rule_dict in rules:
cnt += 1
created_rules[cnt] = []
# Get all the rule and subscription parameters
grouping = rule_dict.get('grouping', 'DATASET')
lifetime = rule_dict.get('lifetime', None)
ignore_availability = rule_dict.get('ignore_availability', None)
weight = rule_dict.get('weight', None)
source_replica_expression = rule_dict.get('source_replica_expression', None)
locked = rule_dict.get('locked', None)
if locked == 'True':
locked = True
else:
locked = False
purge_replicas = rule_dict.get('purge_replicas', False)
if purge_replicas == 'True':
purge_replicas = True
else:
purge_replicas = False
rse_expression = str(rule_dict['rse_expression'])
comment = str(subscription['comments'])
subscription_id = str(subscription['id'])
account = subscription['account']
copies = int(rule_dict['copies'])
activity = rule_dict.get('activity', 'User Subscriptions')
try:
validate_schema(name='activity', obj=activity)
except InputValidationError as error:
logging.error(prepend_str + 'Error validating the activity %s' % (str(error)))
activity = 'User Subscriptions'
if lifetime:
lifetime = int(lifetime)
str_activity = "".join(activity.split())
success = False
nattempt = 5
attemptnr = 0
skip_rule_creation = False
selected_rses = []
chained_idx = rule_dict.get('chained_idx', None)
if chained_idx:
params = {}
if rule_dict.get('associated_site_idx', None):
params['associated_site_idx'] = rule_dict.get('associated_site_idx', None)
logging.debug('%s Chained subscription identified. Will use %s', prepend_str, str(created_rules[chained_idx]))
algorithm = rule_dict.get('algorithm', None)
selected_rses = select_algorithm(algorithm, created_rules[chained_idx], params)
else:
# In the case of chained subscription, don't use rseselector but use the rses returned by the algorithm
if split_rule:
rses = parse_expression(rse_expression)
list_of_rses = [rse['id'] for rse in rses]
# Check that some rule doesn't already exist for this DID and subscription
preferred_rse_ids = []
for rule in list_rules(filters={'subscription_id': subscription_id, 'scope': did['scope'], 'name': did['name']}):
already_existing_rses = [(rse['rse'], rse['id']) for rse in parse_expression(rule['rse_expression'])]
for rse, rse_id in already_existing_rses:
if (rse_id in list_of_rses) and (rse_id not in preferred_rse_ids):
preferred_rse_ids.append(rse_id)
if len(preferred_rse_ids) >= copies:
skip_rule_creation = True
rse_id_dict = {}
for rse in rses:
rse_id_dict[rse['id']] = rse['rse']
try:
rseselector = RSESelector(account=account, rses=rses, weight=weight, copies=copies - len(preferred_rse_ids))
selected_rses = [rse_id_dict[rse_id] for rse_id, _, _ in rseselector.select_rse(0, preferred_rse_ids=preferred_rse_ids, copies=copies, blacklist=blacklisted_rse_id)]
except (InsufficientTargetRSEs, InsufficientAccountLimit, InvalidRuleWeight, RSEOverQuota) as error:
logging.warning(prepend_str + 'Problem getting RSEs for subscription "%s" for account %s : %s. Try including blacklisted sites' %
(subscription['name'], account, str(error)))
# Now including the blacklisted sites
try:
rseselector = RSESelector(account=account, rses=rses, weight=weight, copies=copies - len(preferred_rse_ids))
selected_rses = [rse_id_dict[rse_id] for rse_id, _, _ in rseselector.select_rse(0, preferred_rse_ids=preferred_rse_ids, copies=copies, blacklist=[])]
ignore_availability = True
except (InsufficientTargetRSEs, InsufficientAccountLimit, InvalidRuleWeight, RSEOverQuota) as error:
logging.error(prepend_str + 'Problem getting RSEs for subscription "%s" for account %s : %s. Skipping rule creation.' %
(subscription['name'], account, str(error)))
monitor.record_counter(counters='transmogrifier.addnewrule.errortype.%s' % (str(error.__class__.__name__)), delta=1)
# The DID won't be reevaluated at the next cycle
did_success = did_success and True
continue
for attempt in range(0, nattempt):
attemptnr = attempt
nb_rule = 0
# Try to create the rule
try:
if split_rule:
if not skip_rule_creation:
for rse in selected_rses:
if isinstance(selected_rses, dict):
source_replica_expression = selected_rses[rse].get('source_replica_expression', None)
weight = selected_rses[rse].get('weight', None)
logging.info(prepend_str + 'Will insert one rule for %s:%s on %s' % (did['scope'], did['name'], rse))
rule_ids = add_rule(dids=[{'scope': did['scope'], 'name': did['name']}], account=account, copies=1,
rse_expression=rse, grouping=grouping, weight=weight, lifetime=lifetime, locked=locked,
subscription_id=subscription_id, source_replica_expression=source_replica_expression, activity=activity,
purge_replicas=purge_replicas, ignore_availability=ignore_availability, comment=comment)
created_rules[cnt].append(rule_ids[0])
nb_rule += 1
if nb_rule == copies:
success = True
break
else:
rule_ids = add_rule(dids=[{'scope': did['scope'], 'name': did['name']}], account=account, copies=copies,
rse_expression=rse_expression, grouping=grouping, weight=weight, lifetime=lifetime, locked=locked,
subscription_id=subscription['id'], source_replica_expression=source_replica_expression, activity=activity,
purge_replicas=purge_replicas, ignore_availability=ignore_availability, comment=comment)
created_rules[cnt].append(rule_ids[0])
nb_rule += 1
monitor.record_counter(counters='transmogrifier.addnewrule.done', delta=nb_rule)
monitor.record_counter(counters='transmogrifier.addnewrule.activity.%s' % str_activity, delta=nb_rule)
success = True
break
except (InvalidReplicationRule, InvalidRuleWeight, InvalidRSEExpression, StagingAreaRuleRequiresLifetime, DuplicateRule) as error:
# Errors that won't be retried
success = True
logging.error(prepend_str + '%s' % (str(error)))
monitor.record_counter(counters='transmogrifier.addnewrule.errortype.%s' % (str(error.__class__.__name__)), delta=1)
break
except (ReplicationRuleCreationTemporaryFailed, InsufficientTargetRSEs, InsufficientAccountLimit, DatabaseException, RSEBlacklisted) as error:
# Errors to be retried
logging.error(prepend_str + '%s Will perform an other attempt %i/%i' % (str(error), attempt + 1, nattempt))
monitor.record_counter(counters='transmogrifier.addnewrule.errortype.%s' % (str(error.__class__.__name__)), delta=1)
except Exception as error:
# Unexpected errors
monitor.record_counter(counters='transmogrifier.addnewrule.errortype.unknown', delta=1)
exc_type, exc_value, exc_traceback = exc_info()
logging.critical(prepend_str + ''.join(format_exception(exc_type, exc_value, exc_traceback)).strip())
did_success = (did_success and success)
if (attemptnr + 1) == nattempt and not success:
logging.error(prepend_str + 'Rule for %s:%s on %s cannot be inserted' % (did['scope'], did['name'], rse_expression))
else:
logging.info(prepend_str + '%s rule(s) inserted in %f seconds' % (str(nb_rule), time.time() - stime))
except DataIdentifierNotFound as error:
logging.warning(prepend_str + error)
if did_success:
if did['did_type'] == str(DIDType.FILE):
monitor.record_counter(counters='transmogrifier.did.file.processed', delta=1)
elif did['did_type'] == str(DIDType.DATASET):
monitor.record_counter(counters='transmogrifier.did.dataset.processed', delta=1)
elif did['did_type'] == str(DIDType.CONTAINER):
monitor.record_counter(counters='transmogrifier.did.container.processed', delta=1)
monitor.record_counter(counters='transmogrifier.did.processed', delta=1)
identifiers.append({'scope': did['scope'], 'name': did['name'], 'did_type': DIDType.from_sym(did['did_type'])})
time1 = time.time()
# Mark the DIDs as processed
for identifier in chunks(identifiers, 100):
_retrial(set_new_dids, identifier, None)
logging.info(prepend_str + 'Time to set the new flag : %f' % (time.time() - time1))
tottime = time.time() - start_time
for sub in subscriptions:
update_subscription(name=sub['name'], account=sub['account'], metadata={'last_processed': datetime.now()})
logging.info(prepend_str + 'It took %f seconds to process %i DIDs' % (tottime, len(dids)))
logging.debug(prepend_str + 'DIDs processed : %s' % (str(dids)))
monitor.record_counter(counters='transmogrifier.job.done', delta=1)
monitor.record_timer(stat='transmogrifier.job.duration', time=1000 * tottime)
except Exception:
exc_type, exc_value, exc_traceback = exc_info()
logging.critical(prepend_str + ''.join(format_exception(exc_type, exc_value, exc_traceback)).strip())
monitor.record_counter(counters='transmogrifier.job.error', delta=1)
monitor.record_counter(counters='transmogrifier.addnewrule.error', delta=1)
if once is True:
break
if tottime < sleep_time:
logging.info(prepend_str + 'Will sleep for %s seconds' % (sleep_time - tottime))
time.sleep(sleep_time - tottime)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Graceful stop requested')
logging.info(prepend_str + 'Graceful stop done')
def test_heartbeat_payload(self):
""" HEARTBEAT (CORE): Test heartbeat with payload"""
pids = [self.__pid() for _ in range(6)]
threads = [self.__thread() for _ in range(6)]
live('test5', 'host0', pids[0], threads[0], payload='payload1')
live('test5', 'host0', pids[1], threads[1], payload='payload1')
live('test5', 'host0', pids[2], threads[2], payload='payload1')
live('test5', 'host1', pids[3], threads[3], payload='payload2')
live('test5', 'host2', pids[4], threads[4], payload='payload3')
live('test5', 'host3', pids[5], threads[5], payload='payload4')
assert list_payload_counts('test5') == {
'payload4': 1,
'payload2': 1,
'payload3': 1,
'payload1': 3
}
die('test5', 'host0', pids[0], threads[0])
die('test5', 'host0', pids[1], threads[1])
die('test5', 'host0', pids[2], threads[2])
die('test5', 'host1', pids[3], threads[3])
die('test5', 'host2', pids[4], threads[4])
die('test5', 'host3', pids[5], threads[5])
assert list_payload_counts('test5') == {}
def submitter(once=False, rses=[], mock=False,
process=0, total_processes=1, thread=0, total_threads=1,
bulk=100, group_bulk=1, group_policy='rule', fts_source_strategy='auto',
activities=None, sleep_time=600, retry_other_fts=False):
"""
Main loop to submit a new transfer primitive to a transfertool.
"""
logging.info('Stager starting - process (%i/%i) thread (%i)' % (process,
total_processes,
total_threads))
try:
scheme = config_get('conveyor', 'scheme')
except NoOptionError:
scheme = None
try:
failover_scheme = config_get('conveyor', 'failover_scheme')
except NoOptionError:
failover_scheme = None
try:
bring_online = config_get('conveyor', 'bring_online')
except NoOptionError:
bring_online = 43200
try:
max_time_in_queue = {}
timelife_conf = config_get('conveyor', 'max_time_in_queue')
timelife_confs = timelife_conf.split(",")
for conf in timelife_confs:
act, timelife = conf.split(":")
max_time_in_queue[act.strip()] = int(timelife.strip())
except NoOptionError:
max_time_in_queue = {}
if 'default' not in max_time_in_queue:
max_time_in_queue['default'] = 168
logging.debug("Maximum time in queue for different activities: %s" % max_time_in_queue)
executable = ' '.join(sys.argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
hb = heartbeat.live(executable, hostname, pid, hb_thread)
logging.info('Stager started - process (%i/%i) thread (%i/%i)' % (process, total_processes,
hb['assign_thread'], hb['nr_threads']))
threadPool = ThreadPool(total_threads)
activity_next_exe_time = defaultdict(time.time)
sleeping = False
while not GRACEFULSTOP.is_set():
try:
if not sleeping:
sleeping = True
hb = heartbeat.live(executable, hostname, pid, hb_thread)
logging.info('Transfer submitter - thread (%i/%i) bulk (%i)' % (hb['assign_thread'], hb['nr_threads'], bulk))
if activities is None:
activities = [None]
if rses:
rse_ids = [rse['id'] for rse in rses]
else:
rse_ids = None
for activity in activities:
if activity_next_exe_time[activity] > time.time():
time.sleep(1)
continue
sleeping = False
logging.info("%s:%s Starting to get stagein transfers for %s" % (process, hb['assign_thread'], activity))
ts = time.time()
transfers = get_stagein_transfers(process=process, total_processes=total_processes, thread=hb['assign_thread'], total_threads=hb['nr_threads'], failover_schemes=failover_scheme,
limit=bulk, activity=activity, rses=rse_ids, mock=mock, schemes=scheme, bring_online=bring_online, retry_other_fts=retry_other_fts)
record_timer('daemons.conveyor.stager.get_stagein_transfers.per_transfer', (time.time() - ts) * 1000 / (len(transfers) if len(transfers) else 1))
record_counter('daemons.conveyor.stager.get_stagein_transfers', len(transfers))
record_timer('daemons.conveyor.stager.get_stagein_transfers.transfers', len(transfers))
logging.info("%s:%s Got %s stagein transfers for %s" % (process, hb['assign_thread'], len(transfers), activity))
# group transfers
logging.info("%s:%s Starting to group transfers for %s" % (process, hb['assign_thread'], activity))
ts = time.time()
grouped_jobs = bulk_group_transfer(transfers, group_policy, group_bulk, fts_source_strategy, max_time_in_queue)
record_timer('daemons.conveyor.stager.bulk_group_transfer', (time.time() - ts) * 1000 / (len(transfers) if len(transfers) else 1))
logging.info("%s:%s Starting to submit transfers for %s" % (process, hb['assign_thread'], activity))
# submit transfers
for external_host in grouped_jobs:
for job in grouped_jobs[external_host]:
# submit transfers
# job_requests = makeRequests(submit_transfer, args_list=[((external_host, job, 'transfer_submitter', process, thread), {})])
job_requests = makeRequests(submit_transfer, args_list=[((), {'external_host': external_host, 'job': job, 'submitter': 'transfer_submitter', 'process': process, 'thread': hb['assign_thread']})])
[threadPool.putRequest(job_req) for job_req in job_requests]
threadPool.wait()
if len(transfers) < group_bulk:
logging.info('%i:%i - only %s transfers for %s which is less than group bulk %s, sleep %s seconds' % (process, hb['assign_thread'], len(transfers), activity, group_bulk, sleep_time))
if activity_next_exe_time[activity] < time.time():
activity_next_exe_time[activity] = time.time() + sleep_time
except:
logging.critical('%s:%s %s' % (process, hb['assign_thread'], traceback.format_exc()))
if once:
break
logging.info('%s:%s graceful stop requested' % (process, hb['assign_thread']))
threadPool.dismissWorkers(total_threads, do_join=True)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('%s:%s graceful stop done' % (process, hb['assign_thread']))
def minos(bulk=1000, once=False, sleep_time=60):
"""
Creates a Minos Worker that gets a list of bad PFNs,
extract the scope, name and rse_id and fill the bad_replicas table.
:param bulk: The number of requests to process.
:param once: Run only once.
:param sleep_time: Time between two cycles.
"""
executable = ' '.join(argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1,
heart_beat['nr_threads'])
logging.info(prepend_str + 'Minos starting')
time.sleep(
10
) # To prevent running on the same partition if all the daemons restart at the same time
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1,
heart_beat['nr_threads'])
states_mapping = {
BadPFNStatus.BAD: BadFilesStatus.BAD,
BadPFNStatus.SUSPICIOUS: BadFilesStatus.SUSPICIOUS,
BadPFNStatus.TEMPORARY_UNAVAILABLE:
BadFilesStatus.TEMPORARY_UNAVAILABLE
}
logging.info(prepend_str + 'Minos started')
chunk_size = 10 # The chunk size used for the commits
while not graceful_stop.is_set():
start_time = time.time()
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1,
heart_beat['nr_threads'])
pfns = []
try:
bad_replicas = {}
temporary_unvailables = {}
pfns = get_bad_pfns(thread=heart_beat['assign_thread'],
total_threads=heart_beat['nr_threads'],
limit=bulk)
# Class the PFNs into bad_replicas and temporary_unavailable
for pfn in pfns:
path = pfn['pfn']
account = pfn['account']
reason = pfn['reason']
expires_at = pfn['expires_at']
state = pfn['state']
if states_mapping[state] in [
BadFilesStatus.BAD, BadFilesStatus.SUSPICIOUS
]:
if (account, reason, state) not in bad_replicas:
bad_replicas[(account, reason, state)] = []
bad_replicas[(account, reason, state)].append(path)
if states_mapping[
state] == BadFilesStatus.TEMPORARY_UNAVAILABLE:
if (account, reason,
expires_at) not in temporary_unvailables:
temporary_unvailables[(account, reason,
expires_at)] = []
temporary_unvailables[(account, reason,
expires_at)].append(path)
# Process the bad and suspicious files
# The scope, name, rse_id are extracted and filled into the bad_replicas table
for account, reason, state in bad_replicas:
pfns = bad_replicas[(account, reason, state)]
logging.info(
prepend_str +
'Declaring %s replicas with state %s and reason %s' %
(len(pfns), str(state), reason))
session = get_session()
schemes = {}
dict_rse = {}
unknown_replicas = []
try:
# Splitting the PFNs by schemes
for pfn in pfns:
scheme = pfn.split(':')[0]
if scheme not in schemes:
schemes[scheme] = []
schemes[scheme].append(pfn)
for scheme in schemes:
_, tmp_dict_rse, tmp_unknown_replicas = get_pfn_to_rse(
schemes[scheme])
for rse_id in tmp_dict_rse:
if rse_id not in dict_rse:
dict_rse[rse_id] = []
dict_rse[rse_id].extend(tmp_dict_rse[rse_id])
unknown_replicas.extend(
tmp_unknown_replicas.get('unknown', []))
# The replicas in unknown_replicas do not exist, so we flush them from bad_pfns
if unknown_replicas:
logging.info(
prepend_str +
'The following replicas are unknown and will be removed : %s'
% str(unknown_replicas))
bulk_delete_bad_pfns(pfns=unknown_replicas,
session=None)
for rse_id in dict_rse:
vo = get_rse_vo(rse_id=rse_id)
vo_str = '' if vo == 'def' else ' on VO ' + vo
logging.debug(prepend_str +
'Running on RSE %s%s with %s replicas' %
(get_rse_name(rse_id=rse_id), vo_str,
len(dict_rse[rse_id])))
nchunk = 0
tot_chunk = int(
math.ceil(len(dict_rse[rse_id]) / chunk_size))
for chunk in chunks(dict_rse[rse_id], chunk_size):
nchunk += 1
logging.debug(prepend_str +
'Running on %s chunk out of %s' %
(nchunk, tot_chunk))
unknown_replicas = declare_bad_file_replicas(
pfns=chunk,
reason=reason,
issuer=account,
status=state,
session=session)
if unknown_replicas:
logging.debug(prepend_str +
'Unknown replicas : %s' %
(str(unknown_replicas)))
bulk_delete_bad_pfns(pfns=chunk, session=session)
session.commit() # pylint: disable=no-member
except Exception:
session.rollback() # pylint: disable=no-member
logging.critical(traceback.format_exc())
# Now get the temporary unavailable and update the replicas states
for account, reason, expires_at in temporary_unvailables:
pfns = temporary_unvailables[(account, reason, expires_at)]
logging.info(
prepend_str +
'Declaring %s replicas temporary available with timeout %s and reason %s'
% (len(pfns), str(expires_at), reason))
logging.debug(prepend_str + 'Extracting RSEs')
schemes = {}
dict_rse = {}
unknown_replicas = []
# Splitting the PFNs by schemes
for pfn in pfns:
scheme = pfn.split(':')[0]
if scheme not in schemes:
schemes[scheme] = []
schemes[scheme].append(pfn)
for scheme in schemes:
_, tmp_dict_rse, tmp_unknown_replicas = get_pfn_to_rse(
schemes[scheme])
for rse_id in tmp_dict_rse:
if rse_id not in dict_rse:
dict_rse[rse_id] = []
dict_rse[rse_id].extend(tmp_dict_rse[rse_id])
unknown_replicas.extend(
tmp_unknown_replicas.get('unknown', []))
# The replicas in unknown_replicas do not exist, so we flush them from bad_pfns
if unknown_replicas:
logging.info(
prepend_str +
'The following replicas are unknown and will be removed : %s'
% str(unknown_replicas))
bulk_delete_bad_pfns(pfns=unknown_replicas, session=None)
for rse_id in dict_rse:
replicas = []
rse = get_rse_name(rse_id=rse_id, session=None)
vo = get_rse_vo(rse_id=rse_id)
rse_vo_str = rse if vo == 'def' else '{} on {}'.format(
rse, vo)
logging.debug(prepend_str +
'Running on RSE %s' % rse_vo_str)
for rep in get_did_from_pfns(pfns=dict_rse[rse_id],
rse_id=None,
session=None):
for pfn in rep:
scope = rep[pfn]['scope']
name = rep[pfn]['name']
replicas.append({
'scope': scope,
'name': name,
'rse_id': rse_id,
'state': ReplicaState.TEMPORARY_UNAVAILABLE,
'pfn': pfn
})
# The following part needs to be atomic
# We update the replicas states to TEMPORARY_UNAVAILABLE
# then insert a row in the bad_replicas table. TODO Update the row if it already exists
# then delete the corresponding rows into the bad_pfns table
logging.debug(prepend_str +
'Running on %s replicas on RSE %s' %
(len(replicas), rse_vo_str))
nchunk = 0
tot_chunk = int(
math.ceil(len(replicas) / float(chunk_size)))
session = get_session()
for chunk in chunks(replicas, chunk_size):
try:
nchunk += 1
logging.debug(prepend_str +
'Running on %s chunk out of %s' %
(nchunk, tot_chunk))
update_replicas_states(chunk,
nowait=False,
session=session)
bulk_add_bad_replicas(
chunk,
account,
state=BadFilesStatus.TEMPORARY_UNAVAILABLE,
reason=None,
expires_at=expires_at,
session=session)
pfns = [entry['pfn'] for entry in chunk]
bulk_delete_bad_pfns(pfns=pfns, session=session)
session.commit() # pylint: disable=no-member
except UnsupportedOperation as error:
session.rollback() # pylint: disable=no-member
logging.error(
prepend_str +
'Problem to bulk update PFNs. PFNs will be updated individually. Error : %s'
% str(error))
for rep in chunk:
logging.debug(prepend_str + 'Working on %s' %
(str(rep)))
try:
get_metadata(rep['scope'], rep['name'])
unavailable_states = []
rep_state = get_replicas_state(
rep['scope'], rep['name'])
unavailable_states.extend(
rep_state.get(
ReplicaState.TEMPORARY_UNAVAILABLE,
[]))
unavailable_states.extend(
rep_state.get(
ReplicaState.BEING_DELETED, []))
unavailable_states.extend(
rep_state.get(ReplicaState.BAD, []))
if rep['rse_id'] in unavailable_states:
logging.info(
prepend_str +
'%s is in unavailable state. Will be removed from the list of bad PFNs'
% str(rep['pfn']))
bulk_delete_bad_pfns(pfns=[rep['pfn']],
session=None)
except DataIdentifierNotFound as error:
logging.error(
prepend_str +
'Will remove %s from the list of bad PFNs'
% str(rep['pfn']))
bulk_delete_bad_pfns(pfns=[rep['pfn']],
session=None)
session = get_session()
except Exception:
session.rollback() # pylint: disable=no-member
logging.critical(traceback.format_exc())
session = get_session()
except Exception as error:
logging.error(prepend_str + '%s' % (str(error)))
tottime = time.time() - start_time
if once:
break
if len(pfns) == bulk:
logging.info(
prepend_str +
'Processed maximum number of pfns according to the bulk size. Restart immediately next cycle'
)
elif tottime < sleep_time:
logging.info(prepend_str + 'Will sleep for %s seconds' %
(sleep_time - tottime))
time.sleep(sleep_time - tottime)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Graceful stop requested')
logging.info(prepend_str + 'Graceful stop done')
def deliver_emails(once=False, send_email=True, thread=0, bulk=1000, delay=10):
'''
Main loop to deliver emails via SMTP.
'''
logging.info('[email] starting - threads (%i) bulk (%i)', thread, bulk)
executable = 'hermes [email]'
hostname = socket.getfqdn()
pid = os.getpid()
heartbeat_thread = threading.current_thread()
sanity_check(executable=executable, hostname=hostname)
# Make an initial heartbeat so that all daemons have the correct worker number on the next try
live(executable=executable,
hostname=hostname,
pid=pid,
thread=heartbeat_thread)
GRACEFUL_STOP.wait(1)
email_from = config_get('messaging-hermes', 'email_from')
while not GRACEFUL_STOP.is_set():
heartbeat = live(executable, hostname, pid, heartbeat_thread)
logging.debug('[email] %i:%i - bulk %i', heartbeat['assign_thread'],
heartbeat['nr_threads'], bulk)
t_start = time.time()
messages = retrieve_messages(bulk=bulk,
thread=heartbeat['assign_thread'],
total_threads=heartbeat['nr_threads'],
event_type='email')
if messages != []:
to_delete = []
for message in messages:
logging.debug('[email] %i:%i - submitting: %s',
heartbeat['assign_thread'],
heartbeat['nr_threads'], str(message))
if PY2:
msg = MIMEText(message['payload']['body'].encode('utf-8'))
else:
msg = MIMEText(message['payload']['body'])
msg['From'] = email_from
msg['To'] = ', '.join(message['payload']['to'])
if PY2:
msg['Subject'] = message['payload']['subject'].encode(
'utf-8')
else:
msg['Subject'] = message['payload']['subject']
if send_email:
smtp = smtplib.SMTP()
smtp.connect()
smtp.sendmail(msg['From'], message['payload']['to'],
msg.as_string())
smtp.quit()
to_delete.append({
'id': message['id'],
'created_at': message['created_at'],
'updated_at': message['created_at'],
'payload': str(message['payload']),
'event_type': 'email'
})
logging.debug('[email] %i:%i - submitting done: %s',
heartbeat['assign_thread'],
heartbeat['nr_threads'], str(message['id']))
delete_messages(to_delete)
logging.info('[email] %i:%i - submitted %i messages',
heartbeat['assign_thread'], heartbeat['nr_threads'],
len(to_delete))
if once:
break
t_delay = delay - (time.time() - t_start)
t_delay = t_delay if t_delay > 0 else 0
if t_delay:
logging.debug('[email] %i:%i - sleeping %s seconds',
heartbeat['assign_thread'], heartbeat['nr_threads'],
t_delay)
time.sleep(t_delay)
logging.debug('[email] %i:%i - graceful stop requested',
heartbeat['assign_thread'], heartbeat['nr_threads'])
die(executable, hostname, pid, heartbeat_thread)
logging.debug('[email] %i:%i - graceful stop done',
heartbeat['assign_thread'], heartbeat['nr_threads'])
def re_evaluator(once=False):
"""
Main loop to check the re-evaluation of dids.
"""
hostname = socket.gethostname()
pid = os.getpid()
current_thread = threading.current_thread()
paused_dids = {} # {(scope, name): datetime}
# Make an initial heartbeat so that all judge-evaluators have the correct worker number on the next try
live(executable='rucio-judge-evaluator', hostname=hostname, pid=pid, thread=current_thread, older_than=60 * 30)
graceful_stop.wait(1)
while not graceful_stop.is_set():
try:
# heartbeat
heartbeat = live(executable='rucio-judge-evaluator', hostname=hostname, pid=pid, thread=current_thread, older_than=60 * 30)
start = time.time() # NOQA
# Refresh paused dids
paused_dids = dict((k, v) for k, v in iteritems(paused_dids) if datetime.utcnow() < v)
# Select a bunch of dids for re evaluation for this worker
dids = get_updated_dids(total_workers=heartbeat['nr_threads'],
worker_number=heartbeat['assign_thread'],
limit=100,
blacklisted_dids=[(InternalScope(key[0], fromExternal=False), key[1]) for key in paused_dids])
logging.debug('re_evaluator[%s/%s] index query time %f fetch size is %d (%d blacklisted)' % (heartbeat['assign_thread'],
heartbeat['nr_threads'],
time.time() - start,
len(dids),
len([(InternalScope(key[0], fromExternal=False), key[1]) for key in paused_dids])))
# If the list is empty, sent the worker to sleep
if not dids and not once:
logging.debug('re_evaluator[%s/%s] did not get any work (paused_dids=%s)' % (heartbeat['assign_thread'], heartbeat['nr_threads'], str(len(paused_dids))))
graceful_stop.wait(30)
else:
done_dids = {}
for did in dids:
if graceful_stop.is_set():
break
# Check if this did has already been operated on
did_tag = '%s:%s' % (did.scope.internal, did.name)
if did_tag in done_dids:
if did.rule_evaluation_action in done_dids[did_tag]:
logging.debug('re_evaluator[%s/%s]: evaluation of %s:%s already done' % (heartbeat['assign_thread'], heartbeat['nr_threads'], did.scope, did.name))
delete_updated_did(id=did.id)
continue
else:
done_dids[did_tag] = []
# Jump paused dids
if (did.scope.internal, did.name) in paused_dids:
continue
try:
start_time = time.time()
re_evaluate_did(scope=did.scope, name=did.name, rule_evaluation_action=did.rule_evaluation_action)
logging.debug('re_evaluator[%s/%s]: evaluation of %s:%s took %f' % (heartbeat['assign_thread'], heartbeat['nr_threads'], did.scope, did.name, time.time() - start_time))
delete_updated_did(id=did.id)
done_dids[did_tag].append(did.rule_evaluation_action)
except DataIdentifierNotFound as e:
delete_updated_did(id=did.id)
except (DatabaseException, DatabaseError) as e:
if match('.*ORA-00054.*', str(e.args[0])):
paused_dids[(did.scope.internal, did.name)] = datetime.utcnow() + timedelta(seconds=randint(60, 600))
logging.warning('re_evaluator[%s/%s]: Locks detected for %s:%s' % (heartbeat['assign_thread'], heartbeat['nr_threads'], did.scope, did.name))
record_counter('rule.judge.exceptions.LocksDetected')
elif match('.*QueuePool.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
elif match('.*ORA-03135.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
else:
logging.error(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
except ReplicationRuleCreationTemporaryFailed as e:
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
logging.warning('re_evaluator[%s/%s]: Replica Creation temporary failed, retrying later for %s:%s' % (heartbeat['assign_thread'], heartbeat['nr_threads'], did.scope, did.name))
except FlushError as e:
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
logging.warning('re_evaluator[%s/%s]: Flush error for %s:%s' % (heartbeat['assign_thread'], heartbeat['nr_threads'], did.scope, did.name))
except (DatabaseException, DatabaseError) as e:
if match('.*QueuePool.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
elif match('.*ORA-03135.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
else:
logging.critical(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
except Exception as e:
logging.critical(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
if once:
break
die(executable='rucio-judge-evaluator', hostname=hostname, pid=pid, thread=current_thread)
def submitter(once=False, rses=None, mock=False,
bulk=100, group_bulk=1, group_policy='rule', source_strategy=None,
activities=None, sleep_time=600, max_sources=4, retry_other_fts=False):
"""
Main loop to submit a new transfer primitive to a transfertool.
"""
try:
scheme = config_get('conveyor', 'scheme')
except NoOptionError:
scheme = None
try:
failover_scheme = config_get('conveyor', 'failover_scheme')
except NoOptionError:
failover_scheme = None
try:
timeout = config_get('conveyor', 'submit_timeout')
timeout = float(timeout)
except NoOptionError:
timeout = None
try:
bring_online = config_get('conveyor', 'bring_online')
except NoOptionError:
bring_online = 43200
try:
max_time_in_queue = {}
timelife_conf = config_get('conveyor', 'max_time_in_queue')
timelife_confs = timelife_conf.split(",")
for conf in timelife_confs:
act, timelife = conf.split(":")
max_time_in_queue[act.strip()] = int(timelife.strip())
except NoOptionError:
max_time_in_queue = {}
if 'default' not in max_time_in_queue:
max_time_in_queue['default'] = 168
logging.debug("Maximum time in queue for different activities: %s", max_time_in_queue)
activity_next_exe_time = defaultdict(time.time)
executable = "conveyor-submitter"
if activities:
activities.sort()
executable += '--activities ' + str(activities)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'], heart_beat['nr_threads'])
logging.info('%s Submitter starting with timeout %s', prepend_str, timeout)
time.sleep(10) # To prevent running on the same partition if all the poller restart at the same time
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'], heart_beat['nr_threads'])
logging.info('%s Transfer submitter started', prepend_str)
while not graceful_stop.is_set():
if activities is None:
activities = [None]
if rses:
rse_ids = [rse['id'] for rse in rses]
else:
rse_ids = None
for activity in activities:
try:
if activity_next_exe_time[activity] > time.time():
graceful_stop.wait(1)
continue
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread, older_than=3600)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'], heart_beat['nr_threads'])
user_transfer = False
if activity in USER_ACTIVITY and USER_TRANSFERS in ['cms']:
logging.info('%s CMS user transfer activity', prepend_str)
user_transfer = True
logging.info('%s Starting to get transfer transfers for %s', prepend_str, activity)
start_time = time.time()
transfers = __get_transfers(total_workers=heart_beat['nr_threads'],
worker_number=heart_beat['assign_thread'],
failover_schemes=failover_scheme,
limit=bulk,
activity=activity,
rses=rse_ids,
schemes=scheme,
mock=mock,
max_sources=max_sources,
bring_online=bring_online,
retry_other_fts=retry_other_fts)
record_timer('daemons.conveyor.transfer_submitter.get_transfers.per_transfer', (time.time() - start_time) * 1000 / (len(transfers) if transfers else 1))
record_counter('daemons.conveyor.transfer_submitter.get_transfers', len(transfers))
GET_TRANSFERS_COUNTER.inc(len(transfers))
record_timer('daemons.conveyor.transfer_submitter.get_transfers.transfers', len(transfers))
logging.info('%s Got %s transfers for %s in %s seconds', prepend_str, len(transfers), activity, time.time() - start_time)
# group transfers
logging.info('%s Starting to group transfers for %s', prepend_str, activity)
start_time = time.time()
grouped_jobs = bulk_group_transfer(transfers, group_policy, group_bulk, source_strategy, max_time_in_queue)
record_timer('daemons.conveyor.transfer_submitter.bulk_group_transfer', (time.time() - start_time) * 1000 / (len(transfers) if transfers else 1))
logging.info('%s Starting to submit transfers for %s', prepend_str, activity)
if TRANSFER_TOOL in ['fts3', 'mock']:
for external_host in grouped_jobs:
if not user_transfer:
for job in grouped_jobs[external_host]:
# submit transfers
submit_transfer(external_host=external_host, job=job, submitter='transfer_submitter',
logging_prepend_str=prepend_str, timeout=timeout)
else:
for _, jobs in iteritems(grouped_jobs[external_host]):
# submit transfers
for job in jobs:
submit_transfer(external_host=external_host, job=job, submitter='transfer_submitter',
logging_prepend_str=prepend_str, timeout=timeout, user_transfer_job=user_transfer)
elif TRANSFER_TOOL == 'globus':
if TRANSFER_TYPE == 'bulk':
# build bulk job file list per external host to send to submit_transfer
for external_host in grouped_jobs:
# pad the job with job_params; irrelevant for globus but needed for further rucio parsing
submitjob = {'files': [], 'job_params': grouped_jobs[''][0].get('job_params')}
for job in grouped_jobs[external_host]:
submitjob.get('files').append(job.get('files')[0])
logging.debug('submitjob: %s' % submitjob)
submit_transfer(external_host=external_host, job=submitjob, submitter='transfer_submitter', logging_prepend_str=prepend_str, timeout=timeout)
else:
# build single job files and individually send to submit_transfer
job_params = grouped_jobs[''][0].get('job_params') if grouped_jobs else None
for external_host in grouped_jobs:
for job in grouped_jobs[external_host]:
for file in job['files']:
singlejob = {'files': [file], 'job_params': job_params}
logging.debug('singlejob: %s' % singlejob)
submit_transfer(external_host=external_host, job=singlejob, submitter='transfer_submitter', logging_prepend_str=prepend_str, timeout=timeout)
else:
logging.error(prepend_str + 'Unknown transfer tool')
if len(transfers) < group_bulk:
logging.info('%s Only %s transfers for %s which is less than group bulk %s, sleep %s seconds', prepend_str, len(transfers), activity, group_bulk, sleep_time)
if activity_next_exe_time[activity] < time.time():
activity_next_exe_time[activity] = time.time() + sleep_time
except Exception:
logging.critical('%s %s', prepend_str, str(traceback.format_exc()))
if once:
break
logging.info('%s Graceful stop requested', prepend_str)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('%s Graceful stop done', prepend_str)
return
def poller_latest(external_hosts, once=False, last_nhours=1, fts_wait=1800):
"""
Main loop to check the status of a transfer primitive with a transfertool.
"""
executable = 'conveyor-poller-latest'
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
logging.info('polling latest %s hours on hosts: %s' %
(last_nhours, external_hosts))
if external_hosts:
if isinstance(external_hosts, str):
external_hosts = [external_hosts]
while not graceful_stop.is_set():
try:
heartbeat.live(executable, hostname, pid, hb_thread)
start_time = time.time()
for external_host in external_hosts:
logging.debug('polling latest %s hours on host: %s' %
(last_nhours, external_host))
ts = time.time()
resps = None
state = [
str(FTSState.FINISHED.name),
str(FTSState.FAILED.name),
str(FTSState.FINISHEDDIRTY.name),
str(FTSState.CANCELED.name)
]
try:
resps = transfer.query_latest(external_host,
state=state,
last_nhours=last_nhours)
except Exception:
logging.error(traceback.format_exc())
record_timer('daemons.conveyor.poller_latest.000-query_latest',
(time.time() - ts) * 1000)
if resps:
logging.info('poller_latest - polling %i requests' %
(len(resps)))
if not resps or resps == []:
if once:
break
logging.info("no requests found. will sleep 60 seconds")
continue
for resp in resps:
try:
ret = request.update_request_state(resp)
# if True, really update request content; if False, only touch request
record_counter(
'daemons.conveyor.poller_latest.update_request_state.%s'
% ret)
except Exception:
logging.error(traceback.format_exc())
if once:
break
time_left = fts_wait - abs(time.time() - start_time)
if time_left > 0:
logging.debug(
"Waiting %s seconds until next FTS terminal state retrieval"
% time_left)
graceful_stop.wait(time_left)
except RequestException as error:
logging.error("Failed to contact FTS server: %s" % (str(error)))
except Exception:
logging.critical(traceback.format_exc())
if once:
return
logging.info('poller_latest - graceful stop requests')
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('poller_latest - graceful stop done')
def fts_throttler(once=False, cycle_interval=3600):
"""
Main loop to automatically configure FTS storages.
"""
graceful_stop.clear()
logging.info('FTS Throttler starting')
executable = 'fts_throttler'
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
current_time = time.time()
graceful_stop.wait(10)
running_instance = False
while not graceful_stop.is_set():
heart_beat = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
if heart_beat['nr_threads'] < 2:
running_instance = True
# this loop cannot be entered by more than one instance at a time.
while not graceful_stop.is_set():
try:
heart_beat = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
prepend_str = 'Thread [%i/%i] : ' % (
heart_beat['assign_thread'], heart_beat['nr_threads'])
logging.info(prepend_str + "fts_throttler start cycle")
if FTSThrottler().revert():
logging.info('revert was successful, now tuning')
FTSThrottler().tune()
logging.info('Tuning finished for this cycle')
else:
logging.warn(
'could not revert, cannot tune unless revert has been done, will try again next cycle.'
)
if once:
break
if time.time() < current_time + cycle_interval:
graceful_stop.wait(
int((current_time + cycle_interval) - time.time()))
current_time = time.time()
except Exception:
logging.critical(prepend_str + 'fts_throttler crashed %s' %
(traceback.format_exc()))
if once:
break
else:
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
logging.info(
prepend_str +
'another fts_throttler instance already exists. will wait')
if time.time() < current_time + cycle_interval:
graceful_stop.wait(
int((current_time + cycle_interval) - time.time()))
current_time = time.time()
logging.info(prepend_str + 'Throttler - graceful stop requested')
# before we stop, try to revert, but only if this instance was running the cycles.
# ! If the cycle info file information is shared between instances, then this implementation must be changed !
if running_instance:
try:
FTSThrottler().revert()
except Exception:
logging.warn('could not revert changes before stopping')
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Throttler - graceful stop done')
def hermes2(once=False, thread=0, bulk=1000, sleep_time=10):
"""
Creates a Hermes2 Worker that can submit messages to different services (InfluXDB, ElasticSearch, ActiveMQ)
The list of services need to be define in the config service in the hermes section.
The list of endpoints need to be defined in rucio.cfg in the hermes section.
:param once: Run only once.
:param thread: Thread number at startup.
:param bulk: The number of requests to process.
:param sleep_time: Time between two cycles.
"""
executable = 'hermes2'
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable,
hostname=hostname,
pid=pid,
thread=hb_thread)
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
# Make an initial heartbeat so that all daemons have the correct worker number on the next try
GRACEFUL_STOP.wait(10)
heart_beat = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
try:
services_list = get('hermes', 'services_list')
services_list = services_list.split(',')
except ConfigNotFound:
logging.debug('No services found, exiting')
sys.exit(1)
if 'influx' in services_list:
try:
influx_endpoint = config_get('hermes', 'influxdb_endpoint', False,
None)
if not influx_endpoint:
logging.error(
'InfluxDB defined in the services list, but no endpoint can be find. Exiting'
)
sys.exit(1)
except Exception as err:
logging.error(err)
if 'elastic' in services_list:
try:
elastic_endpoint = config_get('hermes', 'elastic_endpoint', False,
None)
if not elastic_endpoint:
logging.error(
'Elastic defined in the services list, but no endpoint can be find. Exiting'
)
sys.exit(1)
except Exception as err:
logging.error(err)
if 'activemq' in services_list:
try:
# activemq_endpoint = config_get('hermes', 'activemq_endpoint', False, None)
conns, destination, username, password, use_ssl = setup_activemq(
prepend_str)
if not conns:
logging.error(
'ActiveMQ defined in the services list, cannot be setup')
sys.exit(1)
except Exception as err:
logging.error(err)
while not GRACEFUL_STOP.is_set():
message_status = copy.deepcopy(services_list)
message_statuses = {}
stime = time.time()
try:
start_time = time.time()
heart_beat = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
messages = retrieve_messages(
bulk=bulk,
thread=heart_beat['assign_thread'],
total_threads=heart_beat['nr_threads'])
if messages:
for message in messages:
message_statuses[message['id']] = copy.deepcopy(
services_list)
logging.debug(
'%s Retrieved %i messages retrieved in %s seconds',
prepend_str, len(messages),
time.time() - start_time)
if 'influx' in message_status:
t_time = time.time()
logging.debug('%s Will submit to influxDB', prepend_str)
try:
state = aggregate_to_influx(messages=messages,
bin_size='1m',
endpoint=influx_endpoint,
prepend_str=prepend_str)
except Exception as error:
logging.error('%s Error sending to InfluxDB : %s',
prepend_str, str(error))
state = 500
if state in [204, 200]:
logging.info(
'%s Messages successfully submitted to influxDB in %s seconds',
prepend_str,
time.time() - t_time)
for message in messages:
message_statuses[message['id']].remove('influx')
else:
logging.info('%s Failure to submit to influxDB',
prepend_str)
if 'elastic' in message_status:
t_time = time.time()
try:
state = submit_to_elastic(messages=messages,
endpoint=elastic_endpoint,
prepend_str=prepend_str)
except Exception as error:
logging.error('%s Error sending to Elastic : %s',
prepend_str, str(error))
state = 500
if state in [200, 204]:
logging.info(
'%s Messages successfully submitted to elastic in %s seconds',
prepend_str,
time.time() - t_time)
for message in messages:
message_statuses[message['id']].remove('elastic')
else:
logging.info('%s Failure to submit to elastic',
prepend_str)
if 'emails' in message_status:
t_time = time.time()
try:
to_delete = deliver_emails(messages=messages,
prepend_str=prepend_str)
logging.info(
'%s Messages successfully submitted by emails in %s seconds',
prepend_str,
time.time() - t_time)
for message_id in to_delete:
message_statuses[message_id].remove('emails')
except Exception as error:
logging.error('%s Error sending email : %s',
prepend_str, str(error))
if 'activemq' in message_status:
t_time = time.time()
try:
to_delete = deliver_to_activemq(
messages=messages,
conns=conns,
destination=destination,
username=username,
password=password,
use_ssl=use_ssl,
prepend_str=prepend_str)
logging.info(
'%s Messages successfully submitted to ActiveMQ in %s seconds',
prepend_str,
time.time() - t_time)
for message_id in to_delete:
message_statuses[message_id].remove('activemq')
except Exception as error:
logging.error('%s Error sending to ActiveMQ : %s',
prepend_str, str(error))
to_delete = []
to_update = {}
for message in messages:
status = message_statuses[message['id']]
if not status:
to_delete.append({
'id': message['id'],
'created_at': message['created_at'],
'updated_at': message['created_at'],
'payload': str(message['payload']),
'event_type': message['event_type']
})
else:
status = ",".join(status)
if status not in to_update:
to_update[status] = []
to_update[status].append({
'id':
message['id'],
'created_at':
message['created_at'],
'updated_at':
message['created_at'],
'payload':
str(message['payload']),
'event_type':
message['event_type']
})
logging.info('%s Deleting %s messages', prepend_str,
len(to_delete))
delete_messages(messages=to_delete)
for status in to_update:
logging.info(
'%s Failure to submit %s messages to %s. Will update the message status',
prepend_str, str(len(to_update[status])), status)
update_messages_services(messages=to_update[status],
services=status)
if once:
break
tottime = time.time() - stime
if tottime < sleep_time:
logging.info('%s Will sleep for %s seconds', prepend_str,
sleep_time - tottime)
time.sleep(sleep_time - tottime)
except:
logging.critical(traceback.format_exc())
def receiver(id, total_threads=1, full_mode=False):
"""
Main loop to consume messages from the FTS3 producer.
"""
logging.info('receiver starting in full mode: %s' % full_mode)
executable = ' '.join(sys.argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
# Make an initial heartbeat so that all finishers have the correct worker number on the next try
heartbeat.live(executable, hostname, pid, hb_thread)
brokers_alias = []
brokers_resolved = []
try:
brokers_alias = [
b.strip()
for b in config_get('messaging-fts3', 'brokers').split(',')
]
except Exception:
raise Exception('Could not load brokers from configuration')
logging.info('resolving broker dns alias: %s' % brokers_alias)
brokers_resolved = []
for broker in brokers_alias:
brokers_resolved.append([
str(tmp_broker) for tmp_broker in dns.resolver.query(broker, 'A')
])
brokers_resolved = [
item for sublist in brokers_resolved for item in sublist
]
logging.info('brokers resolved to %s', brokers_resolved)
conns = []
for broker in brokers_resolved:
conns.append(
stomp.Connection(host_and_ports=[
(broker, config_get_int('messaging-fts3', 'port'))
],
use_ssl=True,
ssl_key_file=config_get('messaging-fts3',
'ssl_key_file'),
ssl_cert_file=config_get('messaging-fts3',
'ssl_cert_file'),
ssl_version=ssl.PROTOCOL_TLSv1,
reconnect_attempts_max=999))
logging.info('receiver started')
while not graceful_stop.is_set():
heartbeat.live(executable, hostname, pid, hb_thread)
for conn in conns:
if not conn.is_connected():
logging.info('connecting to %s' %
conn.transport._Transport__host_and_ports[0][0])
record_counter('daemons.messaging.fts3.reconnect.%s' %
conn.transport._Transport__host_and_ports[0]
[0].split('.')[0])
conn.set_listener(
'rucio-messaging-fts3',
Receiver(
broker=conn.transport._Transport__host_and_ports[0],
id=id,
total_threads=total_threads,
full_mode=full_mode))
conn.start()
conn.connect()
conn.subscribe(destination=config_get('messaging-fts3',
'destination'),
id='rucio-messaging-fts3',
ack='auto')
time.sleep(1)
logging.info('receiver graceful stop requested')
for conn in conns:
try:
conn.disconnect()
except Exception:
pass
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('receiver graceful stop done')
def undertaker(worker_number=1,
total_workers=1,
chunk_size=5,
once=False,
sleep_time=60):
"""
Main loop to select and delete dids.
"""
logging.info('Undertaker(%s): starting', worker_number)
logging.info('Undertaker(%s): started', worker_number)
executable = 'undertaker'
hostname = socket.gethostname()
pid = os.getpid()
thread = threading.current_thread()
sanity_check(executable=executable, hostname=hostname)
paused_dids = {} # {(scope, name): datetime}
while not GRACEFUL_STOP.is_set():
try:
heartbeat = live(executable=executable,
hostname=hostname,
pid=pid,
thread=thread,
older_than=6000)
logging.info(
'Undertaker({0[worker_number]}/{0[total_workers]}): Live gives {0[heartbeat]}'
.format(locals()))
start = time.time()
# Refresh paused dids
iter_paused_dids = deepcopy(paused_dids)
for key in iter_paused_dids:
if datetime.utcnow() > paused_dids[key]:
del paused_dids[key]
dids = list_expired_dids(worker_number=heartbeat['assign_thread'],
total_workers=heartbeat['nr_threads'],
limit=10000)
dids = [
did for did in dids
if (did['scope'], did['name']) not in paused_dids
]
if not dids and not once:
logging.info('Undertaker(%s): Nothing to do. sleep 60.',
worker_number)
daemon_sleep(start_time=start,
sleep_time=sleep_time,
graceful_stop=GRACEFUL_STOP)
continue
for chunk in chunks(dids, chunk_size):
try:
logging.info('Undertaker(%s): Receive %s dids to delete',
worker_number, len(chunk))
delete_dids(dids=chunk,
account=InternalAccount('root', vo='def'),
expire_rules=True)
logging.info('Undertaker(%s): Delete %s dids',
worker_number, len(chunk))
record_counter(counters='undertaker.delete_dids',
delta=len(chunk))
except RuleNotFound as error:
logging.error(error)
except (DatabaseException, DatabaseError,
UnsupportedOperation) as e:
if match('.*ORA-00054.*', str(e.args[0])) or match(
'.*55P03.*', str(e.args[0])) or match(
'.*3572.*', str(e.args[0])):
for did in chunk:
paused_dids[(
did['scope'],
did['name'])] = datetime.utcnow() + timedelta(
seconds=randint(600, 2400))
record_counter(
'undertaker.delete_dids.exceptions.LocksDetected')
logging.warning(
'undertaker[%s/%s]: Locks detected for chunk',
heartbeat['assign_thread'],
heartbeat['nr_threads'])
else:
logging.error('Undertaker(%s): Got database error %s.',
worker_number, str(e))
except:
logging.critical(traceback.format_exc())
time.sleep(1)
if once:
break
die(executable=executable, hostname=hostname, pid=pid, thread=thread)
logging.info('Undertaker(%s): graceful stop requested', worker_number)
logging.info('Undertaker(%s): graceful stop done', worker_number)
def transmogrifier(bulk=5, once=False):
"""
Creates a Transmogrifier Worker that gets a list of new DIDs for a given hash,
identifies the subscriptions matching the DIDs and
submit a replication rule for each DID matching a subscription.
:param thread: Thread number at startup.
:param bulk: The number of requests to process.
:param once: Run only once.
"""
executable = ' '.join(argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
while not graceful_stop.is_set():
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
dids, subscriptions = [], []
tottime = 0
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1,
heart_beat['nr_threads'])
try:
for did in list_new_dids(thread=heart_beat['assign_thread'],
total_threads=heart_beat['nr_threads'],
chunk_size=bulk):
dids.append({
'scope': did['scope'],
'did_type': str(did['did_type']),
'name': did['name']
})
sub_dict = {3: []}
for sub in list_subscriptions(None, None):
if sub['state'] != SubscriptionState.INACTIVE and sub[
'lifetime'] and (datetime.now() > sub['lifetime']):
update_subscription(name=sub['name'],
account=sub['account'],
state=SubscriptionState.INACTIVE)
elif sub['state'] in [
SubscriptionState.ACTIVE, SubscriptionState.UPDATED
]:
priority = 3
if 'policyid' in sub:
if int(sub['policyid']) not in sub_dict:
sub_dict[int(sub['policyid'])] = []
priority = int(sub['policyid'])
sub_dict[priority].append(sub)
priorities = sub_dict.keys()
priorities.sort()
for priority in priorities:
subscriptions.extend(sub_dict[priority])
except SubscriptionNotFound, error:
logging.warning(prepend_str + 'No subscriptions defined: %s' %
(str(error)))
time.sleep(10)
continue
except Exception, error:
logging.error(
prepend_str +
'Failed to get list of new DIDs or subscriptions: %s' %
(str(error)))
if once:
break
else:
continue
def poller(once=False,
process=0,
total_processes=1,
thread=0,
total_threads=1,
activities=None,
sleep_time=60,
fts_bulk=100,
db_bulk=1000,
older_than=60,
activity_shares=None):
"""
Main loop to check the status of a transfer primitive with a transfertool.
"""
try:
timeout = config_get('conveyor', 'poll_timeout')
timeout = float(timeout)
except NoOptionError:
timeout = None
logging.info(
'poller starting - process (%i/%i) thread (%i/%i) bulk (%i) timeout (%s)'
% (process, total_processes, thread, total_threads, db_bulk, timeout))
executable = ' '.join(sys.argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
hb = heartbeat.live(executable, hostname, pid, hb_thread)
logging.info('poller started - process (%i/%i) thread (%i/%i) bulk (%i)' %
(process, total_processes, hb['assign_thread'],
hb['nr_threads'], db_bulk))
activity_next_exe_time = defaultdict(time.time)
threadPool = ThreadPool(total_threads)
while not graceful_stop.is_set():
try:
hb = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
logging.debug('poller - thread (%i/%i)' %
(hb['assign_thread'], hb['nr_threads']))
if activities is None:
activities = [None]
for activity in activities:
if activity_next_exe_time[activity] > time.time():
graceful_stop.wait(1)
continue
ts = time.time()
logging.debug(
'%i:%i - start to poll transfers older than %i seconds for activity %s'
% (process, hb['assign_thread'], older_than, activity))
transfs = transfer_core.get_next_transfers(
request_type=[
RequestType.TRANSFER, RequestType.STAGEIN,
RequestType.STAGEOUT
],
state=[RequestState.SUBMITTED],
limit=db_bulk,
older_than=datetime.datetime.utcnow() -
datetime.timedelta(seconds=older_than),
process=process,
total_processes=total_processes,
thread=hb['assign_thread'],
total_threads=hb['nr_threads'],
activity=activity,
activity_shares=activity_shares)
record_timer('daemons.conveyor.poller.000-get_next_transfers',
(time.time() - ts) * 1000)
if transfs:
logging.debug(
'%i:%i - polling %i transfers for activity %s' %
(process, hb['assign_thread'], len(transfs), activity))
xfers_ids = {}
for transf in transfs:
if not transf['external_host'] in xfers_ids:
xfers_ids[transf['external_host']] = []
xfers_ids[transf['external_host']].append(
transf['external_id'])
for external_host in xfers_ids:
for xfers in chunks(xfers_ids[external_host], fts_bulk):
# poll transfers
# xfer_requests = makeRequests(common.poll_transfers, args_list=[((external_host, xfers, process, thread), {})])
xfer_requests = makeRequests(poll_transfers,
args_list=[((), {
'external_host':
external_host,
'xfers':
xfers,
'process':
process,
'thread':
hb['assign_thread'],
'timeout':
timeout
})])
[
threadPool.putRequest(xfer_req)
for xfer_req in xfer_requests
]
threadPool.wait()
if len(transfs) < db_bulk / 2:
logging.info(
"%i:%i - only %s transfers for activity %s, which is less than half of the bulk %s, will sleep %s seconds"
% (process, hb['assign_thread'], len(transfs),
activity, db_bulk, sleep_time))
if activity_next_exe_time[activity] < time.time():
activity_next_exe_time[activity] = time.time(
) + sleep_time
except:
logging.critical(
"%i:%i - %s" %
(process, hb['assign_thread'], traceback.format_exc()))
if once:
break
logging.info('%i:%i - graceful stop requests' %
(process, hb['assign_thread']))
threadPool.dismissWorkers(total_threads, do_join=True)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('%i:%i - graceful stop done' % (process, hb['assign_thread']))
def automatix(sites,
inputfile,
sleep_time,
account,
worker_number=1,
total_workers=1,
once=False,
dataset_lifetime=None,
set_metadata=False):
sleep(sleep_time * (total_workers - worker_number) / total_workers)
executable = ' '.join(argv)
hostname = socket.getfqdn()
pid = getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
while not graceful_stop.is_set():
heartbeat.live(executable, hostname, pid, hb_thread)
starttime = time()
prepend_str = 'Thread [%i/%i] : ' % (worker_number, total_workers)
logging.info(prepend_str + 'Getting data distribution')
probabilities, data = get_data_distribution(inputfile)
logging.debug(prepend_str + 'Probabilities %s' % (probabilities))
account = 'root'
scope = 'tests'
totretries = 3
status = False
for site in sites:
for retry in range(0, totretries):
start_time = time()
tmpdir = tempfile.mkdtemp()
logging.info(prepend_str + 'Running on site %s' % (site))
dic = choose_element(probabilities, data)
metadata = dic['metadata']
metadata['version'] = str(random.randint(0, 1000))
metadata['run_number'] = str(random.randint(0, 100000))
metadata['stream_name'] = 'automatix_stream'
metadata['campaign'] = 'automatix_campaign'
try:
nbfiles = dic['nbfiles']
except KeyError:
nbfiles = 2
logging.warning(
prepend_str +
'No nbfiles defined in the configuration, will use 2')
try:
filesize = dic['filesize']
except KeyError:
filesize = 1000000
logging.warning(
prepend_str +
'No filesize defined in the configuration, will use 1M files'
)
dsn = 'tests:%s.%s.%s.%s.%s.%s' % (
metadata['project'], metadata['run_number'],
metadata['stream_name'], metadata['prod_step'],
metadata['datatype'], metadata['version'])
fnames = []
lfns = []
for dummy_nbfile in range(nbfiles):
fname = '%s.%s' % (metadata['datatype'], generate_uuid())
lfns.append(fname)
fname = '%s/%s' % (tmpdir, fname)
logging.info(
prepend_str +
'Generating file %(fname)s in dataset %(dsn)s' %
locals())
generate_file(fname, filesize)
fnames.append(fname)
logging.info(prepend_str + 'Upload %s to %s' % (dsn, site))
status = upload(files=lfns,
scope=scope,
metadata=metadata,
rse=site,
account=account,
source_dir=tmpdir,
worker_number=worker_number,
total_workers=total_workers,
dataset_lifetime=dataset_lifetime,
did=dsn,
set_metadata=set_metadata)
for fname in fnames:
remove(fname)
rmdir(tmpdir)
if status:
monitor.record_counter(
counters='automatix.addnewdataset.done', delta=1)
monitor.record_counter(
counters='automatix.addnewfile.done', delta=nbfiles)
monitor.record_timer('automatix.datasetinjection',
(time() - start_time) * 1000)
break
else:
logging.info(
prepend_str +
'Failed to upload files. Will retry another time (attempt %s/%s)'
% (str(retry + 1), str(totretries)))
if once is True:
logging.info(prepend_str + 'Run with once mode. Exiting')
break
tottime = time() - starttime
if status:
logging.info(prepend_str +
'It took %s seconds to upload one dataset on %s' %
(str(tottime), str(sites)))
if sleep_time > tottime:
logging.info(prepend_str + 'Will sleep for %s seconds' %
(str(sleep_time - tottime)))
sleep(sleep_time - tottime)
else:
logging.info(prepend_str + 'Retrying a new upload')
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Graceful stop requested')
logging.info(prepend_str + 'Graceful stop done')
def deliver_messages(once=False,
brokers_resolved=None,
thread=0,
bulk=1000,
delay=10,
broker_timeout=3,
broker_retry=3):
'''
Main loop to deliver messages to a broker.
'''
logging.info('[broker] starting - threads (%i) bulk (%i)', thread, bulk)
if not brokers_resolved:
logging.fatal('No brokers resolved.')
return
if not broker_timeout: # Allow zero in config
broker_timeout = None
logging.info('[broker] checking authentication method')
use_ssl = True
try:
use_ssl = config_get_bool('messaging-hermes', 'use_ssl')
except:
logging.info(
'[broker] could not find use_ssl in configuration -- please update your rucio.cfg'
)
port = config_get_int('messaging-hermes', 'port')
vhost = config_get('messaging-hermes',
'broker_virtual_host',
raise_exception=False)
if not use_ssl:
username = config_get('messaging-hermes', 'username')
password = config_get('messaging-hermes', 'password')
port = config_get_int('messaging-hermes', 'nonssl_port')
conns = []
for broker in brokers_resolved:
if not use_ssl:
logging.info(
'[broker] setting up username/password authentication: %s' %
broker)
con = stomp.Connection12(host_and_ports=[(broker, port)],
vhost=vhost,
keepalive=True,
timeout=broker_timeout)
else:
logging.info(
'[broker] setting up ssl cert/key authentication: %s' % broker)
con = stomp.Connection12(
host_and_ports=[(broker, port)],
use_ssl=True,
ssl_key_file=config_get('messaging-hermes', 'ssl_key_file'),
ssl_cert_file=config_get('messaging-hermes', 'ssl_cert_file'),
vhost=vhost,
keepalive=True,
timeout=broker_timeout)
con.set_listener(
'rucio-hermes',
HermesListener(con.transport._Transport__host_and_ports[0]))
conns.append(con)
destination = config_get('messaging-hermes', 'destination')
executable = 'hermes [broker]'
hostname = socket.getfqdn()
pid = os.getpid()
heartbeat_thread = threading.current_thread()
# Make an initial heartbeat so that all daemons have the correct worker number on the next try
sanity_check(executable=executable,
hostname=hostname,
pid=pid,
thread=heartbeat_thread)
GRACEFUL_STOP.wait(1)
while not GRACEFUL_STOP.is_set():
try:
t_start = time.time()
heartbeat = live(executable=executable,
hostname=hostname,
pid=pid,
thread=heartbeat_thread)
logging.debug('[broker] %i:%i - using: %s',
heartbeat['assign_thread'], heartbeat['nr_threads'],
[
conn.transport._Transport__host_and_ports[0][0]
for conn in conns
])
messages = retrieve_messages(bulk=bulk,
thread=heartbeat['assign_thread'],
total_threads=heartbeat['nr_threads'])
if messages:
logging.debug('[broker] %i:%i - retrieved %i messages',
heartbeat['assign_thread'],
heartbeat['nr_threads'], len(messages))
to_delete = []
for message in messages:
try:
conn = random.sample(conns, 1)[0]
if not conn.is_connected():
host_and_ports = conn.transport._Transport__host_and_ports[
0][0]
record_counter('daemons.hermes.reconnect.%s' %
host_and_ports.split('.')[0])
labels = {'host': host_and_ports.split('.')[0]}
RECONNECT_COUNTER.labels(**labels).inc()
if not use_ssl:
logging.info(
'[broker] %i:%i - connecting with USERPASS to %s',
heartbeat['assign_thread'],
heartbeat['nr_threads'], host_and_ports)
conn.connect(username, password, wait=True)
else:
logging.info(
'[broker] %i:%i - connecting with SSL to %s',
heartbeat['assign_thread'],
heartbeat['nr_threads'], host_and_ports)
conn.connect(wait=True)
conn.send(body=json.dumps({
'event_type':
str(message['event_type']).lower(),
'payload':
message['payload'],
'created_at':
str(message['created_at'])
}),
destination=destination,
headers={
'persistent':
'true',
'event_type':
str(message['event_type']).lower()
})
to_delete.append({
'id':
message['id'],
'created_at':
message['created_at'],
'updated_at':
message['created_at'],
'payload':
json.dumps(message['payload']),
'event_type':
message['event_type']
})
except ValueError:
logging.warning('Cannot serialize payload to JSON: %s',
str(message['payload']))
to_delete.append({
'id': message['id'],
'created_at': message['created_at'],
'updated_at': message['created_at'],
'payload': str(message['payload']),
'event_type': message['event_type']
})
continue
except stomp.exception.NotConnectedException as error:
logging.warning(
'Could not deliver message due to NotConnectedException: %s',
str(error))
continue
except stomp.exception.ConnectFailedException as error:
logging.warning(
'Could not deliver message due to ConnectFailedException: %s',
str(error))
continue
except Exception as error:
logging.warning('Could not deliver message: %s',
str(error))
logging.critical(traceback.format_exc())
continue
if str(message['event_type']).lower().startswith(
'transfer') or str(message['event_type']).lower(
).startswith('stagein'):
logging.debug(
'[broker] %i:%i - event_type: %s, scope: %s, name: %s, rse: %s, request-id: %s, transfer-id: %s, created_at: %s',
heartbeat['assign_thread'],
heartbeat['nr_threads'],
str(message['event_type']).lower(),
message['payload'].get('scope', None),
message['payload'].get('name', None),
message['payload'].get('dst-rse', None),
message['payload'].get('request-id', None),
message['payload'].get('transfer-id', None),
str(message['created_at']))
elif str(message['event_type']).lower().startswith(
'dataset'):
logging.debug(
'[broker] %i:%i - event_type: %s, scope: %s, name: %s, rse: %s, rule-id: %s, created_at: %s)',
heartbeat['assign_thread'],
heartbeat['nr_threads'],
str(message['event_type']).lower(),
message['payload']['scope'],
message['payload']['name'],
message['payload']['rse'],
message['payload']['rule_id'],
str(message['created_at']))
elif str(message['event_type']).lower().startswith(
'deletion'):
if 'url' not in message['payload']:
message['payload']['url'] = 'unknown'
logging.debug(
'[broker] %i:%i - event_type: %s, scope: %s, name: %s, rse: %s, url: %s, created_at: %s)',
heartbeat['assign_thread'],
heartbeat['nr_threads'],
str(message['event_type']).lower(),
message['payload']['scope'],
message['payload']['name'],
message['payload']['rse'],
message['payload']['url'],
str(message['created_at']))
else:
logging.debug('[broker] %i:%i - other message: %s',
heartbeat['assign_thread'],
heartbeat['nr_threads'], message)
delete_messages(to_delete)
logging.info('[broker] %i:%i - submitted %i messages',
heartbeat['assign_thread'],
heartbeat['nr_threads'], len(to_delete))
if once:
break
except NoResultFound:
# silence this error: https://its.cern.ch/jira/browse/RUCIO-1699
pass
except:
logging.critical(traceback.format_exc())
t_delay = delay - (time.time() - t_start)
t_delay = t_delay if t_delay > 0 else 0
if t_delay:
logging.debug('[broker] %i:%i - sleeping %s seconds',
heartbeat['assign_thread'], heartbeat['nr_threads'],
t_delay)
time.sleep(t_delay)
for conn in conns:
try:
conn.disconnect()
except Exception:
pass
logging.debug('[broker] %i:%i - graceful stop requested',
heartbeat['assign_thread'], heartbeat['nr_threads'])
die(executable, hostname, pid, heartbeat_thread)
logging.debug('[broker] %i:%i - graceful stop done',
heartbeat['assign_thread'], heartbeat['nr_threads'])
def rule_repairer(once=False):
"""
Main loop to check for STUCK replication rules
"""
hostname = socket.gethostname()
pid = os.getpid()
current_thread = threading.current_thread()
paused_rules = {} # {rule_id: datetime}
# Make an initial heartbeat so that all judge-repairers have the correct worker number on the next try
live(executable='rucio-judge-repairer', hostname=hostname, pid=pid, thread=current_thread, older_than=60 * 30)
graceful_stop.wait(1)
while not graceful_stop.is_set():
try:
# heartbeat
heartbeat = live(executable='rucio-judge-repairer', hostname=hostname, pid=pid, thread=current_thread, older_than=60 * 30)
start = time.time()
# Refresh paused rules
iter_paused_rules = deepcopy(paused_rules)
for key in iter_paused_rules:
if datetime.utcnow() > paused_rules[key]:
del paused_rules[key]
# Select a bunch of rules for this worker to repair
rules = get_stuck_rules(total_workers=heartbeat['nr_threads'],
worker_number=heartbeat['assign_thread'],
delta=-1 if once else 1800,
limit=100,
blacklisted_rules=[key for key in paused_rules])
logging.debug('rule_repairer[%s/%s] index query time %f fetch size is %d' % (heartbeat['assign_thread'], heartbeat['nr_threads'], time.time() - start, len(rules)))
if not rules and not once:
logging.debug('rule_repairer[%s/%s] did not get any work (paused_rules=%s)' % (heartbeat['assign_thread'], heartbeat['nr_threads'], str(len(paused_rules))))
graceful_stop.wait(60)
else:
for rule_id in rules:
rule_id = rule_id[0]
logging.info('rule_repairer[%s/%s]: Repairing rule %s' % (heartbeat['assign_thread'], heartbeat['nr_threads'], rule_id))
if graceful_stop.is_set():
break
try:
start = time.time()
repair_rule(rule_id=rule_id)
logging.debug('rule_repairer[%s/%s]: repairing of %s took %f' % (heartbeat['assign_thread'], heartbeat['nr_threads'], rule_id, time.time() - start))
except (DatabaseException, DatabaseError) as e:
if match('.*ORA-00054.*', str(e.args[0])):
paused_rules[rule_id] = datetime.utcnow() + timedelta(seconds=randint(600, 2400))
logging.warning('rule_repairer[%s/%s]: Locks detected for %s' % (heartbeat['assign_thread'], heartbeat['nr_threads'], rule_id))
record_counter('rule.judge.exceptions.LocksDetected')
elif match('.*QueuePool.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
elif match('.*ORA-03135.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
else:
logging.error(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
except (DatabaseException, DatabaseError) as e:
if match('.*QueuePool.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
elif match('.*ORA-03135.*', str(e.args[0])):
logging.warning(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
else:
logging.critical(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
except Exception as e:
logging.critical(traceback.format_exc())
record_counter('rule.judge.exceptions.%s' % e.__class__.__name__)
if once:
break
die(executable='rucio-judge-repairer', hostname=hostname, pid=pid, thread=current_thread)
def minos_tu_expiration(bulk=1000, once=False, sleep_time=60):
"""
Creates a Minos Temporary Unavailable Replicas Expiration Worker that
gets the list of expired TU replicas and sets them back to AVAILABLE.
:param bulk: The number of requests to process.
:param once: Run only once.
:param sleep_time: Time between two cycles.
"""
executable = 'minos-temporary-expiration'
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prefix = 'minos_temporary_expiration[%i/%i] : ' % (heart_beat['assign_thread'], heart_beat['nr_threads'])
logger = formatted_logger(logging.log, prefix + '%s')
logger(logging.INFO, 'Minos Temporary Expiration starting')
time.sleep(10) # To prevent running on the same partition if all the daemons restart at the same time
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
logger(logging.INFO, 'Minos Temporary Expiration started')
chunk_size = 10 # The chunk size used for the commits
while not graceful_stop.is_set():
start_time = time.time()
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
try:
# Get list of expired TU replicas
logger(logging.INFO, 'Getting list of expired replicas')
expired_replicas = list_expired_temporary_unavailable_replicas(total_workers=heart_beat['nr_threads'],
worker_number=heart_beat['assign_thread'],
limit=1000)
logger(logging.INFO, '%s expired replicas returned', len(expired_replicas))
logger(logging.DEBUG, 'List of expired replicas returned %s', str(expired_replicas))
replicas = []
bad_replicas = []
nchunk = 0
tot_chunk = int(math.ceil(len(expired_replicas) / float(chunk_size)))
session = get_session()
for chunk in chunks(expired_replicas, chunk_size):
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
skip_replica_update = []
# Process and update the replicas in chunks
for replica in chunk:
scope, name, rse_id = replica[0], replica[1], replica[2]
states_dictionary = get_replicas_state(scope=scope, name=name, session=session)
# Check if the replica is not declared bad
# If already declared bad don't update the replica state, but remove from bad_pfns
if not (ReplicaState.BAD in states_dictionary and rse_id in states_dictionary[ReplicaState.BAD]):
replicas.append({'scope': scope, 'name': name, 'rse_id': rse_id, 'state': ReplicaState.AVAILABLE})
else:
skip_replica_update.append((scope, name))
# Remove the replicas from bad_replicas table in chunks
bad_replicas.append({'scope': scope, 'name': name, 'rse_id': rse_id, 'state': BadFilesStatus.TEMPORARY_UNAVAILABLE})
try:
nchunk += 1
logger(logging.DEBUG, 'Running on %s chunk out of %s', nchunk, tot_chunk)
update_replicas_states(replicas, nowait=True, session=session)
bulk_delete_bad_replicas(bad_replicas, session=session)
session.commit() # pylint: disable=no-member
except (ReplicaNotFound, DataIdentifierNotFound) as error:
session.rollback() # pylint: disable=no-member
logger(logging.WARNING, 'One of the replicas does not exist anymore. Updating and deleting one by one. Error : %s', str(error))
for replica in chunk:
scope, name, rse_id = replica[0], replica[1], replica[2]
logger(logging.DEBUG, 'Working on %s:%s on %s', scope, name, rse_id)
try:
# First check if the DID exists
get_metadata(scope, name)
if (scope, name) not in skip_replica_update:
update_replicas_states([{'scope': scope, 'name': name, 'rse_id': rse_id, 'state': ReplicaState.AVAILABLE}, ], nowait=True, session=session)
bulk_delete_bad_replicas([{'scope': scope, 'name': name, 'rse_id': rse_id, 'state': BadFilesStatus.TEMPORARY_UNAVAILABLE}, ], session=session)
session.commit() # pylint: disable=no-member
except DataIdentifierNotFound:
session.rollback() # pylint: disable=no-member
logger(logging.WARNING, 'DID %s:%s does not exist anymore.', scope, name)
bulk_delete_bad_replicas([{'scope': scope, 'name': name, 'rse_id': rse_id, 'state': BadFilesStatus.TEMPORARY_UNAVAILABLE}, ], session=session)
session.commit() # pylint: disable=no-member
except ReplicaNotFound:
session.rollback() # pylint: disable=no-member
logger(logging.WARNING, 'Replica %s:%s on RSEID %s does not exist anymore.', scope, name, rse_id)
bulk_delete_bad_replicas([{'scope': scope, 'name': name, 'rse_id': rse_id, 'state': BadFilesStatus.TEMPORARY_UNAVAILABLE}, ], session=session)
session.commit() # pylint: disable=no-member
session = get_session()
except (DatabaseException, DatabaseError) as error:
if re.match('.*ORA-00054.*', error.args[0]) or re.match('.*ORA-00060.*', error.args[0]) or 'ERROR 1205 (HY000)' in error.args[0]:
logger(logging.WARNING, 'Lock detected when handling request - skipping: %s', str(error))
else:
logger(logging.ERROR, 'Exception', exc_info=True)
session.rollback()
session = get_session()
except Exception:
session.rollback() # pylint: disable=no-member
logger(logging.CRITICAL, str(traceback.format_exc()))
session = get_session()
except Exception:
logger(logging.CRITICAL, str(traceback.format_exc()))
if once:
break
daemon_sleep(start_time=start_time, sleep_time=sleep_time, graceful_stop=graceful_stop)
heartbeat.die(executable, hostname, pid, hb_thread)
logger(logging.INFO, 'Graceful stop requested')
logger(logging.INFO, 'Graceful stop done')
def automatix(sites,
inputfile,
sleep_time,
account,
worker_number=1,
total_workers=1,
scope='tests',
once=False,
dataset_lifetime=None,
set_metadata=False):
sleep(sleep_time * (total_workers - worker_number) / total_workers)
executable = 'automatix'
hostname = socket.getfqdn()
pid = getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
prepend_str = 'Thread [%i/%i] : ' % (worker_number, total_workers)
while not GRACEFUL_STOP.is_set():
heartbeat.live(executable, hostname, pid, hb_thread)
starttime = time()
prepend_str = 'Thread [%i/%i] : ' % (worker_number, total_workers)
logging.info('%s Getting data distribution', prepend_str)
probabilities, data = get_data_distribution(inputfile)
logging.debug('%s Probabilities %s', prepend_str, probabilities)
totretries = 3
status = False
for site in sites:
for retry in range(0, totretries):
start_time = time()
tmpdir = tempfile.mkdtemp()
logging.info('%s Running on site %s', prepend_str, site)
dic = choose_element(probabilities, data)
metadata = dic['metadata']
try:
nbfiles = dic['nbfiles']
except KeyError:
nbfiles = 2
logging.warning(
'%s No nbfiles defined in the configuration, will use 2',
prepend_str)
try:
filesize = dic['filesize']
except KeyError:
filesize = 1000000
logging.warning(
'%s No filesize defined in the configuration, will use 1M files',
prepend_str)
dsn = generate_didname(metadata, None, 'dataset')
fnames = []
lfns = []
physical_fnames = []
for _ in range(nbfiles):
fname = generate_didname(metadata=metadata,
dsn=dsn,
did_type='file')
lfns.append(fname)
logging.info('%s Generating file %s in dataset %s',
prepend_str, fname, dsn)
physical_fname = '%s/%s' % (tmpdir, "".join(
fname.split('/')))
physical_fnames.append(physical_fname)
generate_file(physical_fname, filesize)
fnames.append(fname)
logging.info('%s Upload %s to %s', prepend_str, dsn, site)
dsn = '%s:%s' % (scope, dsn)
status = upload(files=lfns,
scope=scope,
metadata=metadata,
rse=site,
account=account,
source_dir=tmpdir,
worker_number=worker_number,
total_workers=total_workers,
dataset_lifetime=dataset_lifetime,
did=dsn,
set_metadata=set_metadata)
for physical_fname in physical_fnames:
remove(physical_fname)
rmdir(tmpdir)
if status:
monitor.record_counter(
counters='automatix.addnewdataset.done', delta=1)
monitor.record_counter(
counters='automatix.addnewfile.done', delta=nbfiles)
monitor.record_timer('automatix.datasetinjection',
(time() - start_time) * 1000)
break
else:
logging.info(
'%s Failed to upload files. Will retry another time (attempt %s/%s)',
prepend_str, str(retry + 1), str(totretries))
if once is True:
logging.info('%s Run with once mode. Exiting', prepend_str)
break
tottime = time() - starttime
if status:
logging.info('%s It took %s seconds to upload one dataset on %s',
prepend_str, str(tottime), str(sites))
if sleep_time > tottime:
logging.info('%s Will sleep for %s seconds', prepend_str,
str(sleep_time - tottime))
sleep(sleep_time - tottime)
else:
logging.info('%s Retrying a new upload', prepend_str)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info('%s Graceful stop requested', prepend_str)
logging.info('%s Graceful stop done', prepend_str)
def declare_suspicious_replicas_bad(once=False, younger_than=3, nattempts=10, rse_expression='MOCK', vos=None, max_replicas_per_rse=100):
"""
Main loop to check for available replicas which are labeled as suspicious
Gets a list of suspicious replicas that are listed as AVAILABLE in 'replicas' table
and available on other RSE. Finds surls of these replicas and declares them as bad.
:param once: If True, the loop is run just once, otherwise the daemon continues looping until stopped.
:param younger_than: The number of days since which bad_replicas table will be searched
for finding replicas declared 'SUSPICIOUS' at a specific RSE ('rse_expression'),
but 'AVAILABLE' on other RSE(s).
:param nattempts: The minimum number of appearances in the bad_replica DB table
in order to appear in the resulting list of replicas for recovery.
:param rse_expression: Search for suspicious replicas on RSEs matching the 'rse_expression'.
:param vos: VOs on which to look for RSEs. Only used in multi-VO mode.
If None, we either use all VOs if run from "def",
:param max_replicas_per_rse: Maximum number of replicas which are allowed to be labeled as bad per RSE.
If more is found, processing is skipped and warning is printed.
:returns: None
"""
# assembling the worker name identifier ('executable') including the rses from <rse_expression>
# in order to have the possibility to detect a start of a second instance with the same set of RSES
executable = argv[0]
multi_vo = config_get_bool('common', 'multi_vo', raise_exception=False, default=False)
if not multi_vo:
if vos:
logging.warning('Ignoring argument vos, this is only applicable in a multi-VO setup.')
vos = ['def']
else:
if vos:
invalid = set(vos) - set([v['vo'] for v in list_vos()])
if invalid:
msg = 'VO{} {} cannot be found'.format('s' if len(invalid) > 1 else '', ', '.join([repr(v) for v in invalid]))
raise VONotFound(msg)
else:
vos = [v['vo'] for v in list_vos()]
logging.info('replica_recoverer: This instance will work on VO%s: %s' % ('s' if len(vos) > 1 else '', ', '.join([v for v in vos])))
# Don't require a result from the expression at each VO, only raise if we can't get a result from any of them
rses = []
exceptions_raised = 0
for vo in vos:
try:
parsed_rses = parse_expression(expression=rse_expression, filter={'vo': vo})
except InvalidRSEExpression:
exceptions_raised += 1
parsed_rses = []
for rse in parsed_rses:
rses.append(rse['id'])
if exceptions_raised == len(vos):
raise InvalidRSEExpression('RSE Expression resulted in an empty set.')
rses.sort()
executable += ' --rse-expression ' + str(rses)
sanity_check(executable=executable, hostname=socket.gethostname())
# make an initial heartbeat - expected only one replica-recoverer thread on one node
# heartbeat mechanism is used in this daemon only for information purposes
# (due to expected low load, the actual DB query does not filter the result based on worker number)
live(executable=executable, hostname=socket.gethostname(), pid=os.getpid(), thread=threading.current_thread())
# wait a moment in case all workers started at the same time
GRACEFUL_STOP.wait(1)
while not GRACEFUL_STOP.is_set():
try:
# issuing the heartbeat for a second time to make all workers aware of each other (there is only 1 worker allowed for this daemon)
heartbeat = live(executable=executable, hostname=socket.gethostname(), pid=os.getpid(), thread=threading.current_thread())
total_workers = heartbeat['nr_threads']
worker_number = heartbeat['assign_thread']
# there is only 1 worker allowed for this daemon
if total_workers != 1:
logging.error('replica_recoverer: Another running instance on %s has been detected. Stopping gracefully.', socket.gethostname())
die(executable=executable, hostname=socket.gethostname(), pid=os.getpid(), thread=threading.current_thread())
break
start = time.time()
logging.info('replica_recoverer[%i/%i]: ready to query replicas at RSE %s,'
+ ' reported suspicious in the last %i days at least %i times which are available on other RSEs.', # NOQA: W503
worker_number, total_workers, rse_expression, younger_than, nattempts)
getfileskwargs = {'younger_than': younger_than,
'nattempts': nattempts,
'exclude_states': ['B', 'R', 'D', 'L', 'T'],
'available_elsewhere': True,
'is_suspicious': True}
# Don't require a result from the expression at each VO, only raise if we can't get a result from any of them
recoverable_replicas = []
exceptions_raised = 0
for vo in vos:
try:
recoverable_replicas.extend(get_suspicious_files(rse_expression, filter={'vo': vo}, **getfileskwargs))
except InvalidRSEExpression:
exceptions_raised += 1
if exceptions_raised == len(vos):
raise InvalidRSEExpression('RSE Expression resulted in an empty set.')
logging.info('replica_recoverer[%i/%i]: suspicious replica query took %.2f seconds, total of %i replicas were found.',
worker_number, total_workers, time.time() - start, len(recoverable_replicas))
if not recoverable_replicas and not once:
logging.info('replica_recoverer[%i/%i]: found %i recoverable suspicious replicas. Sleeping for 60 seconds.', worker_number, total_workers, len(recoverable_replicas))
GRACEFUL_STOP.wait(60)
else:
logging.info('replica_recoverer[%i/%i]: looking for replica surls.', worker_number, total_workers)
start = time.time()
surls_to_recover = {} # dictionary of { vo1: {rse1: [surl1, surl2, ... ], rse2: ...}, vo2:... }
cnt_surl_not_found = 0
for replica in recoverable_replicas:
scope = replica['scope']
name = replica['name']
vo = scope.vo
rse = replica['rse']
rse_id = replica['rse_id']
if GRACEFUL_STOP.is_set():
break
if vo not in surls_to_recover:
surls_to_recover[vo] = {}
if rse_id not in surls_to_recover[vo]:
surls_to_recover[vo][rse_id] = []
# for each suspicious replica, we get its surl through the list_replicas function
surl_not_found = True
for rep in list_replicas([{'scope': scope, 'name': name}]):
for site in rep['rses']:
if site == rse_id:
surls_to_recover[vo][rse_id].append(rep['rses'][site][0])
surl_not_found = False
if surl_not_found:
cnt_surl_not_found += 1
logging.warning('replica_recoverer[%i/%i]: skipping suspicious replica %s on %s, no surls were found.', worker_number, total_workers, name, rse)
logging.info('replica_recoverer[%i/%i]: found %i/%i surls (took %.2f seconds), declaring them as bad replicas now.',
worker_number, total_workers, len(recoverable_replicas) - cnt_surl_not_found, len(recoverable_replicas), time.time() - start)
for vo in surls_to_recover:
for rse_id in surls_to_recover[vo]:
logging.info('replica_recoverer[%i/%i]: ready to declare %i bad replica(s) on %s: %s.',
worker_number, total_workers, len(surls_to_recover[vo][rse_id]), rse, str(surls_to_recover[vo][rse_id]))
if len(surls_to_recover[vo][rse_id]) > max_replicas_per_rse:
logging.warning('replica_recoverer[%i/%i]: encountered more than %i suspicious replicas (%s) on %s. Please investigate.',
worker_number, total_workers, max_replicas_per_rse, str(len(surls_to_recover[vo][rse_id])), rse)
else:
declare_bad_file_replicas(pfns=surls_to_recover[vo][rse_id], reason='Suspicious. Automatic recovery.', issuer=InternalAccount('root', vo=vo), status=BadFilesStatus.BAD, session=None)
logging.info('replica_recoverer[%i/%i]: finished declaring bad replicas on %s.', worker_number, total_workers, rse)
except (DatabaseException, DatabaseError) as err:
if match('.*QueuePool.*', str(err.args[0])):
logging.warning(traceback.format_exc())
record_counter('replica.recoverer.exceptions.%s', err.__class__.__name__)
elif match('.*ORA-03135.*', str(err.args[0])):
logging.warning(traceback.format_exc())
record_counter('replica.recoverer.exceptions.%s', err.__class__.__name__)
else:
logging.critical(traceback.format_exc())
record_counter('replica.recoverer.exceptions.%s', err.__class__.__name__)
except Exception as err:
logging.critical(traceback.format_exc())
record_counter('replica.recoverer.exceptions.%s', err.__class__.__name__)
if once:
break
die(executable=executable, hostname=socket.gethostname(), pid=os.getpid(), thread=threading.current_thread())
logging.info('replica_recoverer[%i/%i]: graceful stop done', worker_number, total_workers)
def OAuthManager(once=False, loop_rate=300, max_rows=100, sleep_time=300):
"""
Main loop to delete all expired tokens, refresh tokens eligible
for refresh and delete all expired OAuth session parameters.
It was decided to have only 1 daemon for all 3 of these cleanup activities.
:param once: If True, the loop is run just once, otherwise the daemon continues looping until stopped.
:param loop_rate: obsolete, please use sleep_time instead. The number of seconds the daemon will wait before running next loop of operations.
:param max_rows: Max number of DB rows to deal with per operation.
:param sleep_time: The number of seconds the daemon will wait before running next loop of operations.
:returns: None
"""
if sleep_time == OAuthManager.__defaults__[
3] and loop_rate != OAuthManager.__defaults__[1]:
sleep_time = loop_rate
executable = 'oauth-manager'
sanity_check(executable=executable, hostname=socket.gethostname())
# make an initial heartbeat
heartbeat = live(executable=executable,
hostname=socket.gethostname(),
pid=os.getpid(),
thread=threading.current_thread())
prepend_str = 'oauth_manager [%i/%i] : ' % (heartbeat['assign_thread'],
heartbeat['nr_threads'])
logger = formatted_logger(logging.log, prepend_str + '%s')
# wait a moment in case all workers started at the same time
GRACEFUL_STOP.wait(1)
while not GRACEFUL_STOP.is_set():
start = time.time()
# issuing the heartbeat for a second time to make all workers aware of each other
heartbeat = live(executable=executable,
hostname=socket.gethostname(),
pid=os.getpid(),
thread=threading.current_thread())
prepend_str = 'oauth_manager [%i/%i] : ' % (heartbeat['assign_thread'],
heartbeat['nr_threads'])
logger = formatted_logger(logging.log, prepend_str + '%s')
ndeleted = 0
ndeletedreq = 0
nrefreshed = 0
try:
# ACCESS TOKEN REFRESH - better to run first (in case some of the refreshed tokens needed deletion after this step)
logger(logging.INFO,
'----- START ----- ACCESS TOKEN REFRESH ----- ')
logger(logging.INFO,
'starting to query tokens for automatic refresh')
nrefreshed = refresh_jwt_tokens(heartbeat['nr_threads'],
heartbeat['assign_thread'] + 1,
refreshrate=int(sleep_time),
limit=max_rows)
logger(logging.INFO, 'successfully refreshed %i tokens',
nrefreshed)
logger(logging.INFO, '----- END ----- ACCESS TOKEN REFRESH ----- ')
record_counter(name='oauth_manager.tokens.refreshed',
delta=nrefreshed)
except (DatabaseException, DatabaseError) as err:
if match('.*QueuePool.*', str(err.args[0])):
logger(logging.WARNING, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
elif match('.*ORA-03135.*', str(err.args[0])):
logger(logging.WARNING, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
else:
logger(logging.CRITICAL, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
except Exception as err:
logger(logging.CRITICAL, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
try:
# waiting 1 sec as DBs does not store milisecond and tokens
# eligible for deletion after refresh might not get dleeted otherwise
GRACEFUL_STOP.wait(1)
# EXPIRED TOKEN DELETION
logger(logging.INFO,
'----- START ----- DELETION OF EXPIRED TOKENS ----- ')
logger(logging.INFO, 'starting to delete expired tokens')
ndeleted += delete_expired_tokens(heartbeat['nr_threads'],
heartbeat['assign_thread'] + 1,
limit=max_rows)
logger(logging.INFO, 'deleted %i expired tokens', ndeleted)
logger(logging.INFO,
'----- END ----- DELETION OF EXPIRED TOKENS ----- ')
record_counter(name='oauth_manager.tokens.deleted', delta=ndeleted)
except (DatabaseException, DatabaseError) as err:
if match('.*QueuePool.*', str(err.args[0])):
logger(logging.WARNING, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
elif match('.*ORA-03135.*', str(err.args[0])):
logger(logging.WARNING, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
else:
logger(logging.CRITICAL, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
except Exception as err:
logger(logging.CRITICAL, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
try:
# DELETING EXPIRED OAUTH SESSION PARAMETERS
logger(
logging.INFO,
'----- START ----- DELETION OF EXPIRED OAUTH SESSION REQUESTS ----- '
)
logger(logging.INFO,
'starting deletion of expired OAuth session requests')
ndeletedreq += delete_expired_oauthrequests(
heartbeat['nr_threads'],
heartbeat['assign_thread'] + 1,
limit=max_rows)
logger(
logging.INFO,
'expired parameters of %i authentication requests were deleted',
ndeletedreq)
logger(
logging.INFO,
'----- END ----- DELETION OF EXPIRED OAUTH SESSION REQUESTS ----- '
)
record_counter(name='oauth_manager.oauthreq.deleted',
delta=ndeletedreq)
except (DatabaseException, DatabaseError) as err:
if match('.*QueuePool.*', str(err.args[0])):
logger(logging.WARNING, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
elif match('.*ORA-03135.*', str(err.args[0])):
logger(logging.WARNING, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
else:
logger(logging.CRITICAL, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
except Exception as err:
logger(logging.CRITICAL, traceback.format_exc())
record_counter('oauth_manager.exceptions.{exception}',
labels={'exception': err.__class__.__name__})
tottime = time.time() - start
logger(
logging.INFO,
'took %f seconds to delete %i tokens, %i session parameters and refreshed %i tokens',
tottime, ndeleted, ndeletedreq, nrefreshed)
record_timer(name='oauth_manager.duration', time=1000 * tottime)
if once:
break
else:
daemon_sleep(start_time=start,
sleep_time=sleep_time,
graceful_stop=GRACEFUL_STOP)
die(executable=executable,
hostname=socket.gethostname(),
pid=os.getpid(),
thread=threading.current_thread())
logger(logging.INFO, 'graceful stop done')
def collection_replica_update(once=False, limit=1000):
"""
Main loop to check and update the collection replicas.
"""
logging.info('collection_replica_update: starting')
logging.info('collection_replica_update: started')
# Make an initial heartbeat so that all abacus-collection-replica daemons have the correct worker number on the next try
executable = 'abacus-collection-replica'
hostname = socket.gethostname()
pid = os.getpid()
current_thread = threading.current_thread()
live(executable=executable,
hostname=hostname,
pid=pid,
thread=current_thread)
while not graceful_stop.is_set():
try:
# Heartbeat
heartbeat = live(executable=executable,
hostname=hostname,
pid=pid,
thread=current_thread)
# Select a bunch of collection replicas for to update for this worker
start = time.time() # NOQA
replicas = get_cleaned_updated_collection_replicas(
total_workers=heartbeat['nr_threads'] - 1,
worker_number=heartbeat['assign_thread'],
limit=limit)
logging.debug('Index query time %f size=%d' %
(time.time() - start, len(replicas)))
# If the list is empty, sent the worker to sleep
if not replicas and not once:
logging.info(
'collection_replica_update[%s/%s] did not get any work' %
(heartbeat['assign_thread'], heartbeat['nr_threads'] - 1))
time.sleep(10)
else:
for replica in replicas:
if graceful_stop.is_set():
break
start_time = time.time()
update_collection_replica(replica)
logging.debug(
'collection_replica_update[%s/%s]: update of collection replica "%s" took %f'
%
(heartbeat['assign_thread'], heartbeat['nr_threads'] -
1, replica['id'], time.time() - start_time))
if limit and len(replicas) < limit and not once:
time.sleep(10)
except Exception:
logging.error(traceback.format_exc())
if once:
break
logging.info('collection_replica_update: graceful stop requested')
die(executable=executable,
hostname=hostname,
pid=pid,
thread=current_thread)
logging.info('collection_replica_update: graceful stop done')
def finisher(once=False,
process=0,
total_processes=1,
thread=0,
total_threads=1,
sleep_time=60,
activities=None,
bulk=100,
db_bulk=1000):
"""
Main loop to update the replicas and rules based on finished requests.
"""
logging.info(
'finisher starting - process (%i/%i) thread (%i/%i) db_bulk(%i) bulk (%i)'
% (process, total_processes, thread, total_threads, db_bulk, bulk))
try:
suspicious_patterns = []
pattern = get(section='conveyor',
option='suspicious_pattern',
session=None)
pattern = str(pattern)
patterns = pattern.split(",")
for pat in patterns:
suspicious_patterns.append(re.compile(pat.strip()))
except ConfigNotFound:
suspicious_patterns = []
logging.debug("Suspicious patterns: %s" %
[pat.pattern for pat in suspicious_patterns])
executable = ' '.join(sys.argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
# Make an initial heartbeat so that all finishers have the correct worker number on the next try
hb = heartbeat.live(executable, hostname, pid, hb_thread)
graceful_stop.wait(1)
sleeping = False
while not graceful_stop.is_set():
start_time = time.time()
try:
hb = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
prepend_str = 'Thread [%i/%i] : ' % (hb['assign_thread'] + 1,
hb['nr_threads'])
if activities is None:
activities = [None]
if sleeping:
logging.info(prepend_str +
'Nothing to do. will sleep %s seconds' %
(sleep_time))
graceful_stop.wait(sleep_time)
sleeping = True
for activity in activities:
ts = time.time()
reqs = request_core.get_next(
request_type=[
RequestType.TRANSFER, RequestType.STAGEIN,
RequestType.STAGEOUT
],
state=[
RequestState.DONE, RequestState.FAILED,
RequestState.LOST, RequestState.SUBMITTING,
RequestState.SUBMISSION_FAILED,
RequestState.NO_SOURCES, RequestState.ONLY_TAPE_SOURCES
],
limit=db_bulk,
older_than=datetime.datetime.utcnow(),
activity=activity,
process=process,
total_processes=total_processes,
thread=hb['assign_thread'],
total_threads=hb['nr_threads'])
record_timer('daemons.conveyor.finisher.000-get_next',
(time.time() - ts) * 1000)
if reqs:
logging.debug(prepend_str +
'Updating %i requests for activity %s' %
(len(reqs), activity))
sleeping = False
for chunk in chunks(reqs, bulk):
try:
ts = time.time()
__handle_requests(chunk, suspicious_patterns)
record_timer(
'daemons.conveyor.finisher.handle_requests',
(time.time() - ts) * 1000 /
(len(chunk) if len(chunk) else 1))
record_counter(
'daemons.conveyor.finisher.handle_requests',
len(chunk))
except:
logging.warn(str(traceback.format_exc()))
if reqs:
logging.debug(
prepend_str +
'Finish to update %s finished requests for activity %s'
% (len(reqs), activity))
except (DatabaseException, DatabaseError) as error:
if isinstance(
error.args[0],
tuple) and (re.match('.*ORA-00054.*', error.args[0][0]) or
('ERROR 1205 (HY000)' in error.args[0][0])):
logging.warn(
prepend_str +
'Lock detected when handling request - skipping: %s' %
(str(error)))
else:
logging.error(prepend_str + '%s' % (traceback.format_exc()))
sleeping = False
except:
sleeping = False
logging.critical(prepend_str + '%s' % (traceback.format_exc()))
end_time = time.time()
time_diff = end_time - start_time
if time_diff < sleep_time:
logging.info(prepend_str + 'Sleeping for a while : %s seconds' %
(sleep_time - time_diff))
graceful_stop.wait(sleep_time - time_diff)
if once:
return
logging.info(prepend_str + 'Graceful stop requests')
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Graceful stop done')
def reaper(rses,
include_rses,
exclude_rses,
vos=None,
chunk_size=100,
once=False,
greedy=False,
scheme=None,
delay_seconds=0,
sleep_time=60,
auto_exclude_threshold=100,
auto_exclude_timeout=600):
"""
Main loop to select and delete files.
:param rses: List of RSEs the reaper should work against. If empty, it considers all RSEs.
:param include_rses: RSE expression to include RSEs.
:param exclude_rses: RSE expression to exclude RSEs from the Reaper.
:param vos: VOs on which to look for RSEs. Only used in multi-VO mode.
If None, we either use all VOs if run from "def", or the current VO otherwise.
:param chunk_size: The size of chunk for deletion.
:param once: If True, only runs one iteration of the main loop.
:param greedy: If True, delete right away replicas with tombstone.
:param scheme: Force the reaper to use a particular protocol, e.g., mock.
:param delay_seconds: The delay to query replicas in BEING_DELETED state.
:param sleep_time: Time between two cycles.
:param auto_exclude_threshold: Number of service unavailable exceptions after which the RSE gets temporarily excluded.
:param auto_exclude_timeout: Timeout for temporarily excluded RSEs.
"""
hostname = socket.getfqdn()
executable = 'reaper2'
pid = os.getpid()
hb_thread = threading.current_thread()
sanity_check(executable=executable, hostname=hostname)
heart_beat = live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
logging.info('%s Reaper starting', prepend_str)
if not once:
GRACEFUL_STOP.wait(
10
) # To prevent running on the same partition if all the reapers restart at the same time
heart_beat = live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
logging.info('%s Reaper started', prepend_str)
while not GRACEFUL_STOP.is_set():
# try to get auto exclude parameters from the config table. Otherwise use CLI parameters.
try:
auto_exclude_threshold = get('reaper',
'auto_exclude_threshold',
default=auto_exclude_threshold)
auto_exclude_timeout = get('reaper',
'auto_exclude_timeout',
default=auto_exclude_timeout)
except ConfigNotFound:
pass
# Check if there is a Judge Evaluator backlog
try:
max_evaluator_backlog_count = get('reaper',
'max_evaluator_backlog_count')
except ConfigNotFound:
max_evaluator_backlog_count = None
try:
max_evaluator_backlog_duration = get(
'reaper', 'max_evaluator_backlog_duration')
except ConfigNotFound:
max_evaluator_backlog_duration = None
if max_evaluator_backlog_count or max_evaluator_backlog_duration:
backlog = get_evaluation_backlog()
if max_evaluator_backlog_count and \
backlog[0] and \
max_evaluator_backlog_duration and \
backlog[1] and \
backlog[0] > max_evaluator_backlog_count and \
backlog[1] < datetime.utcnow() - timedelta(minutes=max_evaluator_backlog_duration):
logging.error(
'%s Reaper: Judge evaluator backlog count and duration hit, stopping operation',
prepend_str)
GRACEFUL_STOP.wait(30)
continue
elif max_evaluator_backlog_count and backlog[
0] and backlog[0] > max_evaluator_backlog_count:
logging.error(
'%s Reaper: Judge evaluator backlog count hit, stopping operation',
prepend_str)
GRACEFUL_STOP.wait(30)
continue
elif max_evaluator_backlog_duration and backlog[
1] and backlog[1] < datetime.utcnow() - timedelta(
minutes=max_evaluator_backlog_duration):
logging.error(
'%s Reaper: Judge evaluator backlog duration hit, stopping operation',
prepend_str)
GRACEFUL_STOP.wait(30)
continue
rses_to_process = get_rses_to_process(rses, include_rses, exclude_rses,
vos)
if not rses_to_process:
logging.error(
'%s Reaper: No RSEs found. Will sleep for 30 seconds',
prepend_str)
GRACEFUL_STOP.wait(30)
continue
start_time = time.time()
try:
staging_areas = []
dict_rses = {}
heart_beat = live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
tot_needed_free_space = 0
for rse in rses_to_process:
# Check if the RSE is a staging area
if rse['staging_area']:
staging_areas.append(rse['rse'])
# Check if RSE is blacklisted
if rse['availability'] % 2 == 0:
logging.debug('%s RSE %s is blacklisted for delete',
prepend_str, rse['rse'])
continue
max_being_deleted_files, needed_free_space, used, free, only_delete_obsolete = __check_rse_usage(
rse['rse'], rse['id'], prepend_str)
# Check if greedy mode
if greedy:
dict_rses[(rse['rse'], rse['id'])] = [
1000000000000, max_being_deleted_files,
only_delete_obsolete
]
tot_needed_free_space += 1000000000000
else:
if needed_free_space:
dict_rses[(rse['rse'], rse['id'])] = [
needed_free_space, max_being_deleted_files,
only_delete_obsolete
]
tot_needed_free_space += needed_free_space
else:
logging.debug('%s Nothing to delete on %s',
prepend_str, rse['rse'])
# Ordering the RSEs based on the needed free space
sorted_dict_rses = OrderedDict(
sorted(dict_rses.items(), key=itemgetter(1), reverse=True))
logging.debug(
'%s List of RSEs to process ordered by needed space desc : %s',
prepend_str, str(sorted_dict_rses))
# Get the mapping between the RSE and the hostname used for deletion. The dictionary has RSE as key and (hostanme, rse_info) as value
rses_hostname_mapping = get_rses_to_hostname_mapping()
# logging.debug('%s Mapping RSEs to hostnames used for deletion : %s', prepend_str, str(rses_hostname_mapping))
list_rses_mult = []
# Loop over the RSEs. rse_key = (rse, rse_id) and fill list_rses_mult that contains all RSEs to process with different multiplicity
for rse_key in dict_rses:
rse_name, rse_id = rse_key
# The length of the deletion queue scales inversily with the number of workers
# The ceil increase the weight of the RSE with small amount of files to delete
max_workers = ceil(dict_rses[rse_key][0] /
tot_needed_free_space * 1000 /
heart_beat['nr_threads'])
list_rses_mult.extend([
(rse_name, rse_id, dict_rses[rse_key][0],
dict_rses[rse_key][1]) for _ in range(int(max_workers))
])
random.shuffle(list_rses_mult)
for rse_name, rse_id, needed_free_space, max_being_deleted_files in list_rses_mult:
result = REGION.get('pause_deletion_%s' % rse_id,
expiration_time=120)
if result is not NO_VALUE:
logging.warning(
'%s Not enough replicas to delete on %s during the previous cycle. Deletion paused for a while',
prepend_str, rse_name)
continue
result = REGION.get('temporary_exclude_%s' % rse_id,
expiration_time=auto_exclude_timeout)
if result is not NO_VALUE:
logging.warning(
'%s Too many failed attempts for %s in last cycle. RSE is temporarly excluded.',
prepend_str, rse_name)
labels = {'rse': rse_name}
EXCLUDED_RSE_GAUGE.labels(**labels).set(1)
continue
labels = {'rse': rse_name}
EXCLUDED_RSE_GAUGE.labels(**labels).set(0)
logging.debug(
'%s Working on %s. Percentage of the total space needed %.2f',
prepend_str, rse_name,
needed_free_space / tot_needed_free_space * 100)
rse_hostname, rse_info = rses_hostname_mapping[rse_id]
rse_hostname_key = '%s,%s' % (rse_id, rse_hostname)
payload_cnt = list_payload_counts(executable,
older_than=600,
hash_executable=None,
session=None)
# logging.debug('%s Payload count : %s', prepend_str, str(payload_cnt))
tot_threads_for_hostname = 0
tot_threads_for_rse = 0
for key in payload_cnt:
if key and key.find(',') > -1:
if key.split(',')[1] == rse_hostname:
tot_threads_for_hostname += payload_cnt[key]
if key.split(',')[0] == str(rse_id):
tot_threads_for_rse += payload_cnt[key]
max_deletion_thread = get_max_deletion_threads_by_hostname(
rse_hostname)
if rse_hostname_key in payload_cnt and tot_threads_for_hostname >= max_deletion_thread:
logging.debug(
'%s Too many deletion threads for %s on RSE %s. Back off',
prepend_str, rse_hostname, rse_name)
# Might need to reschedule a try on this RSE later in the same cycle
continue
logging.info(
'%s Nb workers on %s smaller than the limit (current %i vs max %i). Starting new worker on RSE %s',
prepend_str, rse_hostname, tot_threads_for_hostname,
max_deletion_thread, rse_name)
live(executable,
hostname,
pid,
hb_thread,
older_than=600,
hash_executable=None,
payload=rse_hostname_key,
session=None)
logging.debug('%s Total deletion workers for %s : %i',
prepend_str, rse_hostname,
tot_threads_for_hostname + 1)
# List and mark BEING_DELETED the files to delete
del_start_time = time.time()
only_delete_obsolete = dict_rses[(rse_name, rse_id)][2]
try:
with monitor.record_timer_block(
'reaper.list_unlocked_replicas'):
if only_delete_obsolete:
logging.debug(
'%s Will run list_and_mark_unlocked_replicas on %s. No space needed, will only delete EPOCH tombstoned replicas',
prepend_str, rse_name)
replicas = list_and_mark_unlocked_replicas(
limit=chunk_size,
bytes=needed_free_space,
rse_id=rse_id,
delay_seconds=delay_seconds,
only_delete_obsolete=only_delete_obsolete,
session=None)
logging.debug(
'%s list_and_mark_unlocked_replicas on %s for %s bytes in %s seconds: %s replicas',
prepend_str, rse_name, needed_free_space,
time.time() - del_start_time, len(replicas))
if len(replicas) < chunk_size:
logging.info(
'%s Not enough replicas to delete on %s (%s requested vs %s returned). Will skip any new attempts on this RSE until next cycle',
prepend_str, rse_name, chunk_size, len(replicas))
REGION.set('pause_deletion_%s' % rse_id, True)
except (DatabaseException, IntegrityError,
DatabaseError) as error:
logging.error('%s %s', prepend_str, str(error))
continue
except Exception:
logging.critical('%s %s', prepend_str,
str(traceback.format_exc()))
# Physical deletion will take place there
try:
prot = rsemgr.create_protocol(rse_info,
'delete',
scheme=scheme)
for file_replicas in chunks(replicas, 100):
# Refresh heartbeat
live(executable,
hostname,
pid,
hb_thread,
older_than=600,
hash_executable=None,
payload=rse_hostname_key,
session=None)
del_start_time = time.time()
for replica in file_replicas:
try:
replica['pfn'] = str(
list(
rsemgr.lfns2pfns(
rse_settings=rse_info,
lfns=[{
'scope':
replica['scope'].external,
'name': replica['name'],
'path': replica['path']
}],
operation='delete',
scheme=scheme).values())[0])
except (ReplicaUnAvailable,
ReplicaNotFound) as error:
logging.warning(
'%s Failed get pfn UNAVAILABLE replica %s:%s on %s with error %s',
prepend_str, replica['scope'],
replica['name'], rse_name, str(error))
replica['pfn'] = None
except Exception:
logging.critical('%s %s', prepend_str,
str(traceback.format_exc()))
deleted_files = delete_from_storage(
file_replicas, prot, rse_info, staging_areas,
prepend_str, auto_exclude_threshold)
logging.info('%s %i files processed in %s seconds',
prepend_str, len(file_replicas),
time.time() - del_start_time)
# Then finally delete the replicas
del_start = time.time()
with monitor.record_timer_block(
'reaper.delete_replicas'):
delete_replicas(rse_id=rse_id, files=deleted_files)
logging.debug(
'%s delete_replicas successed on %s : %s replicas in %s seconds',
prepend_str, rse_name, len(deleted_files),
time.time() - del_start)
monitor.record_counter(counters='reaper.deletion.done',
delta=len(deleted_files))
DELETION_COUNTER.inc(len(deleted_files))
except Exception:
logging.critical('%s %s', prepend_str,
str(traceback.format_exc()))
if once:
break
tottime = time.time() - start_time
if tottime < sleep_time:
logging.info('%s Will sleep for %s seconds', prepend_str,
sleep_time - tottime)
GRACEFUL_STOP.wait(sleep_time - tottime)
except DatabaseException as error:
logging.warning('%s Reaper: %s', prepend_str, str(error))
except Exception:
logging.critical('%s %s', prepend_str, str(traceback.format_exc()))
finally:
if once:
break
die(executable=executable, hostname=hostname, pid=pid, thread=hb_thread)
logging.info('%s Graceful stop requested', prepend_str)
logging.info('%s Graceful stop done', prepend_str)
return
def reaper(rses=[],
worker_number=0,
total_workers=1,
chunk_size=100,
once=False,
scheme=None):
"""
Main loop to select and delete files.
:param rses: List of RSEs the reaper should work against. If empty, it considers all RSEs.
:param worker_number: The worker number.
:param total_workers: The total number of workers.
:param chunk_size: the size of chunk for deletion.
:param once: If True, only runs one iteration of the main loop.
:param scheme: Force the reaper to use a particular protocol, e.g., mock.
"""
logging.info('Starting Light Reaper %s-%s: Will work on RSEs: %s',
worker_number, total_workers, str(rses))
pid = os.getpid()
thread = threading.current_thread()
hostname = socket.gethostname()
executable = ' '.join(sys.argv)
hash_executable = hashlib.sha256(sys.argv[0] + ''.join(rses)).hexdigest()
sanity_check(executable=None, hostname=hostname)
while not GRACEFUL_STOP.is_set():
try:
# heartbeat
heartbeat = live(executable=executable,
hostname=hostname,
pid=pid,
thread=thread,
hash_executable=hash_executable)
logging.info(
'Light Reaper({0[worker_number]}/{0[total_workers]}): Live gives {0[heartbeat]}'
.format(locals()))
nothing_to_do = True
random.shuffle(rses)
for rse_id in rses:
replicas = list_expired_temporary_dids(
rse_id=rse_id,
limit=chunk_size,
worker_number=worker_number,
total_workers=total_workers)
rse = rse_core.get_rse_name(rse_id=rse_id)
rse_info = rsemgr.get_rse_info(rse)
rse_protocol = rse_core.get_rse_protocols(rse_id=rse_id)
prot = rsemgr.create_protocol(rse_info,
'delete',
scheme=scheme)
deleted_replicas = []
try:
prot.connect()
for replica in replicas:
nothing_to_do = False
try:
# pfn = str(rsemgr.lfns2pfns(rse_settings=rse_info,
# lfns=[{'scope': replica['scope'].external, 'name': replica['name'], 'path': replica['path']}],
# operation='delete', scheme=scheme).values()[0])
pfn = 's3://%s%s%s' % (prot.attributes['hostname'],
prot.attributes['prefix'],
replica['name'])
# logging.debug('Light Reaper %s-%s: Deletion ATTEMPT of %s:%s as %s on %s', worker_number, total_workers, replica['scope'], replica['name'], pfn, rse)
start = time.time()
prot.delete(pfn)
duration = time.time() - start
logging.info(
'Light Reaper %s-%s: Deletion SUCCESS of %s:%s as %s on %s in %s seconds',
worker_number, total_workers, replica['scope'],
replica['name'], pfn, rse, duration)
add_message(
'deletion-done', {
'scope': replica['scope'].external,
'name': replica['name'],
'rse': rse,
'rse_id': rse_id,
'file-size': replica.get('bytes') or 0,
'bytes': replica.get('bytes') or 0,
'url': pfn,
'duration': duration,
'protocol': prot.attributes['scheme']
})
deleted_replicas.append(replica)
except SourceNotFound:
err_msg = 'Light Reaper %s-%s: Deletion NOTFOUND of %s:%s as %s on %s' % (
worker_number, total_workers, replica['scope'],
replica['name'], pfn, rse)
logging.warning(err_msg)
deleted_replicas.append(replica)
except (ServiceUnavailable, RSEAccessDenied,
ResourceTemporaryUnavailable) as error:
err_msg = 'Light Reaper %s-%s: Deletion NOACCESS of %s:%s as %s on %s: %s' % (
worker_number, total_workers, replica['scope'],
replica['name'], pfn, rse, str(error))
logging.warning(err_msg)
add_message(
'deletion-failed', {
'scope': replica['scope'].external,
'name': replica['name'],
'rse': rse,
'rse_id': rse_id,
'file-size': replica['bytes'] or 0,
'bytes': replica['bytes'] or 0,
'url': pfn,
'reason': str(error),
'protocol': prot.attributes['scheme']
})
except:
logging.critical(traceback.format_exc())
finally:
prot.close()
delete_temporary_dids(dids=deleted_replicas)
if once:
break
if once:
break
if nothing_to_do:
logging.info(
'Light Reaper %s-%s: Nothing to do. I will sleep for 60s',
worker_number, total_workers)
time.sleep(60)
except DatabaseException as error:
logging.warning('Reaper: %s', str(error))
except:
logging.critical(traceback.format_exc())
die(executable=executable,
hostname=hostname,
pid=pid,
thread=thread,
hash_executable=hash_executable)
logging.info('Graceful stop requested')
logging.info('Graceful stop done')
return
def atropos(thread,
bulk,
date_check,
dry_run=True,
grace_period=86400,
once=True,
unlock=False,
spread_period=0,
purge_replicas=False):
"""
Creates an Atropos Worker that gets a list of rules which have an eol_at expired and delete them.
:param thread: Thread number at startup.
:param bulk: The number of requests to process.
:param grace_period: The grace_period for the rules.
:param once: Run only once.
"""
sleep_time = 60
executable = ' '.join(argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
now = datetime.datetime.now()
hb = heartbeat.live(executable, hostname, pid, hb_thread)
time.sleep(10)
hb = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (hb['assign_thread'] + 1,
hb['nr_threads'])
logging.debug(prepend_str + 'Starting worker')
summary = {}
lifetime_exceptions = {}
rand = random.Random(hb['assign_thread'])
for excep in rucio.core.lifetime_exception.list_exceptions(
exception_id=None,
states=[
LifetimeExceptionsState.APPROVED,
],
session=None):
if '%s:%s' % (excep['scope'],
excep['name']) not in lifetime_exceptions:
lifetime_exceptions['%s:%s' %
(excep['scope'],
excep['name'])] = excep['expires_at']
elif lifetime_exceptions['%s:%s' %
(excep['scope'],
excep['name'])] < excep['expires_at']:
lifetime_exceptions['%s:%s' %
(excep['scope'],
excep['name'])] = excep['expires_at']
logging.debug(prepend_str +
'%s active exceptions' % len(lifetime_exceptions))
if not dry_run and date_check > now:
logging.error(
prepend_str +
'Atropos cannot run in non-dry-run mode for date in the future')
else:
while not GRACEFUL_STOP.is_set():
hb = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (hb['assign_thread'] + 1,
hb['nr_threads'])
stime = time.time()
try:
rules = get_rules_beyond_eol(date_check,
thread,
hb['nr_threads'] - 1,
session=None)
logging.info(prepend_str + '%s rules to process' %
(len(rules)))
for rule_idx, rule in enumerate(rules, start=1):
did = '%s:%s' % (rule.scope, rule.name)
logging.debug(prepend_str +
'Working on rule %s on DID %s on %s' %
(rule.id, did, rule.rse_expression))
if (rule_idx % 1000) == 0:
logging.info(prepend_str + '%s/%s rules processed' %
(rule_idx, len(rules)))
# We compute the expected eol_at
try:
rses = parse_expression(rule.rse_expression)
except InvalidRSEExpression:
logging.warning(
prepend_str +
'Rule %s has an RSE expression that results in an empty set: %s'
% (rule.id, rule.rse_expression))
continue
eol_at = rucio.core.lifetime_exception.define_eol(
rule.scope, rule.name, rses)
if eol_at != rule.eol_at:
logging.warning(
prepend_str +
'The computed eol %s differs from the one recorded %s for rule %s on %s at %s'
% (eol_at, rule.eol_at, rule.id, did,
rule.rse_expression))
try:
update_rule(rule.id, options={'eol_at': eol_at})
except RuleNotFound:
logging.warning(prepend_str +
'Cannot find rule %s on DID %s' %
(rule.id, did))
continue
# Check the exceptions
if did in lifetime_exceptions:
if eol_at > lifetime_exceptions[did]:
logging.info(
prepend_str +
'Rule %s on DID %s on %s has longer expiration date than the one requested : %s'
% (rule.id, did, rule.rse_expression,
lifetime_exceptions[did]))
else:
# If eol_at < requested extension, update eol_at
logging.info(
prepend_str +
'Updating rule %s on DID %s on %s according to the exception till %s'
% (rule.id, did, rule.rse_expression,
lifetime_exceptions[did]))
eol_at = lifetime_exceptions[did]
try:
update_rule(rule.id,
options={
'eol_at':
lifetime_exceptions[did]
})
except RuleNotFound:
logging.warning(
prepend_str +
'Cannot find rule %s on DID %s' %
(rule.id, did))
continue
# Now check that the new eol_at is expired
if eol_at and eol_at < date_check:
no_locks = True
for lock in get_dataset_locks(rule.scope, rule.name):
if lock['rule_id'] == rule[4]:
no_locks = False
if lock['rse_id'] not in summary:
summary[lock['rse_id']] = {}
if did not in summary[lock['rse_id']]:
summary[lock['rse_id']][did] = {
'length': lock['length'] or 0,
'bytes': lock['bytes'] or 0
}
if no_locks:
logging.warning(
prepend_str +
'Cannot find a lock for rule %s on DID %s' %
(rule.id, did))
if not dry_run:
lifetime = grace_period + rand.randrange(
spread_period + 1)
logging.info(
prepend_str +
'Setting %s seconds lifetime for rule %s' %
(lifetime, rule.id))
options = {'lifetime': lifetime}
if purge_replicas:
options = {'purge_replicas': True}
if rule.locked and unlock:
logging.info(prepend_str + 'Unlocking rule %s',
rule.id)
options['locked'] = False
try:
update_rule(rule.id, options=options)
except RuleNotFound:
logging.warning(
prepend_str +
'Cannot find rule %s on DID %s' %
(rule.id, did))
continue
except Exception:
exc_type, exc_value, exc_traceback = exc_info()
logging.critical(''.join(
format_exception(exc_type, exc_value,
exc_traceback)).strip())
for rse_id in summary:
tot_size, tot_files, tot_datasets = 0, 0, 0
for did in summary[rse_id]:
tot_datasets += 1
tot_files += summary[rse_id][did].get('length', 0)
tot_size += summary[rse_id][did].get('bytes', 0)
vo = get_rse_vo(rse_id=rse_id)
logging.info(
prepend_str +
'For RSE %s %s %s datasets will be deleted representing %s files and %s bytes'
% (get_rse_name(rse_id=rse_id), '' if vo == 'def' else
'on VO ' + vo, tot_datasets, tot_files, tot_size))
if once:
break
else:
tottime = time.time() - stime
if tottime < sleep_time:
logging.info(prepend_str + 'Will sleep for %s seconds' %
(str(sleep_time - tottime)))
time.sleep(sleep_time - tottime)
continue
logging.info(prepend_str + 'Graceful stop requested')
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Graceful stop done')
def finisher(once=False,
sleep_time=60,
activities=None,
bulk=100,
db_bulk=1000):
"""
Main loop to update the replicas and rules based on finished requests.
"""
try:
conveyor_config = {item[0]: item[1] for item in items('conveyor')}
except ConfigNotFound:
logging.log(logging.INFO, 'No configuration found for conveyor')
conveyor_config = {}
# Get suspicious patterns
suspicious_patterns = conveyor_config.get('suspicious_pattern', [])
if suspicious_patterns:
pattern = str(suspicious_patterns)
patterns = pattern.split(",")
suspicious_patterns = [re.compile(pat.strip()) for pat in patterns]
logging.debug("Suspicious patterns: %s" %
[pat.pattern for pat in suspicious_patterns])
retry_protocol_mismatches = conveyor_config.get(
'retry_protocol_mismatches', False)
executable = 'conveyor-finisher'
if activities:
activities.sort()
executable += '--activities ' + str(activities)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
# Make an initial heartbeat so that all finishers have the correct worker number on the next try
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prefix = 'conveyor-finisher[%i/%i] : ' % (heart_beat['assign_thread'],
heart_beat['nr_threads'])
logger = formatted_logger(logging.log, prefix + '%s')
logger(logging.INFO, 'Finisher starting - db_bulk(%i) bulk (%i)', db_bulk,
bulk)
graceful_stop.wait(10)
while not graceful_stop.is_set():
start_time = time.time()
try:
heart_beat = heartbeat.live(executable,
hostname,
pid,
hb_thread,
older_than=3600)
prefix = 'conveyor-finisher[%i/%i] : ' % (
heart_beat['assign_thread'], heart_beat['nr_threads'])
logger = formatted_logger(logging.log, prefix + '%s')
logger(logging.DEBUG, 'Starting new cycle')
if activities is None:
activities = [None]
for activity in activities:
logger(logging.DEBUG, 'Working on activity %s', activity)
time1 = time.time()
reqs = request_core.get_next(
request_type=[
RequestType.TRANSFER, RequestType.STAGEIN,
RequestType.STAGEOUT
],
state=[
RequestState.DONE, RequestState.FAILED,
RequestState.LOST, RequestState.SUBMITTING,
RequestState.SUBMISSION_FAILED,
RequestState.NO_SOURCES,
RequestState.ONLY_TAPE_SOURCES,
RequestState.MISMATCH_SCHEME
],
limit=db_bulk,
older_than=datetime.datetime.utcnow(),
total_workers=heart_beat['nr_threads'],
worker_number=heart_beat['assign_thread'],
mode_all=True,
hash_variable='rule_id')
record_timer('daemons.conveyor.finisher.000-get_next',
(time.time() - time1) * 1000)
time2 = time.time()
if reqs:
logger(logging.DEBUG,
'Updating %i requests for activity %s', len(reqs),
activity)
for chunk in chunks(reqs, bulk):
try:
time3 = time.time()
__handle_requests(chunk,
suspicious_patterns,
retry_protocol_mismatches,
logger=logger)
record_timer(
'daemons.conveyor.finisher.handle_requests',
(time.time() - time3) * 1000 /
(len(chunk) if chunk else 1))
record_counter(
'daemons.conveyor.finisher.handle_requests',
len(chunk))
except Exception as error:
logger(logging.WARNING, '%s', str(error))
if reqs:
logger(
logging.DEBUG,
'%s Finish to update %s finished requests for activity %s in %s seconds',
len(reqs), activity,
time.time() - time2)
except (DatabaseException, DatabaseError) as error:
if re.match('.*ORA-00054.*', error.args[0]) or re.match(
'.*ORA-00060.*',
error.args[0]) or 'ERROR 1205 (HY000)' in error.args[0]:
logger(logging.WARNING,
'Lock detected when handling request - skipping: %s',
str(error))
else:
logger(logging.ERROR, 'Exception', exc_info=True)
except Exception:
logger(logging.CRITICAL, 'Exception', exc_info=True)
if once:
return
end_time = time.time()
time_diff = end_time - start_time
if time_diff < sleep_time:
logger(logging.INFO, 'Sleeping for a while : %s seconds',
(sleep_time - time_diff))
graceful_stop.wait(sleep_time - time_diff)
logger(logging.INFO, 'Graceful stop requests')
heartbeat.die(executable, hostname, pid, hb_thread)
logger(logging.INFO, 'Graceful stop done')
def test_old_heartbeat_cleanup(self):
pids = [self.__pid() for _ in range(2)]
thread = self.__thread()
live('test1', 'host0', pids[0], thread)
live('test2', 'host0', pids[1], thread)
live('test1', 'host1', pids[0], thread)
live('test2', 'host1', pids[1], thread)
live('test1', 'host2', pids[0], thread)
live('test2', 'host2', pids[1], thread)
assert len(list_heartbeats()) == 6
@transactional_session
def __forge_updated_at(session=None):
two_days_ago = datetime.utcnow() - timedelta(days=2)
a_dozen_hours_ago = datetime.utcnow() - timedelta(hours=12)
session.query(Heartbeats).filter_by(hostname='host1').update(
{'updated_at': two_days_ago})
session.query(Heartbeats).filter_by(hostname='host2').update(
{'updated_at': a_dozen_hours_ago})
__forge_updated_at()
# Default expiration delay. Host1 health checks should get removed.
sanity_check(executable=None, hostname=None)
assert len(list_heartbeats()) == 4
# Custom expiration delay. Host2 health checks should get removed too.
sanity_check('test2',
'host2',
expiration_delay=timedelta(hours=5).total_seconds())
assert len(list_heartbeats()) == 2
def minos_tu_expiration(bulk=1000, once=False, sleep_time=60):
"""
Creates a Minos Temporary Unavailable Replicas Expiration Worker that
gets the list of expired TU replicas and sets them back to AVAILABLE.
:param bulk: The number of requests to process.
:param once: Run only once.
:param sleep_time: Time between two cycles.
"""
executable = ' '.join(argv)
hostname = socket.getfqdn()
pid = os.getpid()
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
hb_thread = threading.current_thread()
heartbeat.sanity_check(executable=executable, hostname=hostname)
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1, heart_beat['nr_threads'])
logging.info(prepend_str + 'Minos Temporary Expiration starting')
time.sleep(10) # To prevent running on the same partition if all the daemons restart at the same time
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1, heart_beat['nr_threads'])
logging.info(prepend_str + 'Minos Temporary Expiration started')
chunk_size = 10 # The chunk size used for the commits
while not graceful_stop.is_set():
start_time = time.time()
heart_beat = heartbeat.live(executable, hostname, pid, hb_thread)
prepend_str = 'Thread [%i/%i] : ' % (heart_beat['assign_thread'] + 1, heart_beat['nr_threads'])
try:
# Get list of expired TU replicas
logging.info(prepend_str + 'Getting list of expired replicas')
expired_replicas = list_expired_temporary_unavailable_replicas(total_workers=heart_beat['nr_threads'] - 1,
worker_number=heart_beat['assign_thread'],
limit=1000)
logging.info(prepend_str + '%s expired replicas returned' % len(expired_replicas))
logging.debug(prepend_str + 'List of expired replicas returned %s' % str(expired_replicas))
replicas = []
bad_replicas = []
for replica in expired_replicas:
replicas.append({'scope': replica[0], 'name': replica[1], 'rse_id': replica[2], 'state': ReplicaState.AVAILABLE})
bad_replicas.append({'scope': replica[0], 'name': replica[1], 'rse_id': replica[2], 'state': BadFilesStatus.TEMPORARY_UNAVAILABLE})
session = get_session()
for chunk in chunks(replicas, chunk_size):
# Process and update the replicas in chunks
update_replicas_states(chunk, nowait=True, session=session)
for chunk in chunks(bad_replicas, chunk_size):
# Remove the replicas from bad_replicas table in chunks
bulk_delete_bad_replicas(chunk, session=session)
session.commit() # pylint: disable=no-member
except Exception as error:
logging.error(prepend_str + '%s' % (str(error)))
tottime = time.time() - start_time
if once:
break
if tottime < sleep_time:
logging.info(prepend_str + 'Will sleep for %s seconds' % (sleep_time - tottime))
time.sleep(sleep_time - tottime)
heartbeat.die(executable, hostname, pid, hb_thread)
logging.info(prepend_str + 'Graceful stop requested')
logging.info(prepend_str + 'Graceful stop done')
