def _submit_transfers(transfertool_obj, transfers, job_params, submitter='submitter', timeout=None, logger=logging.log):
"""
helper function for submit_transfers. Performs the actual submission of one or more transfers.
If the bulk submission of multiple transfers fails due to duplicate submissions, the exception
is propagated to the caller context, which is then responsible for calling this function again for each
of the transfers separately.
"""
logger(logging.INFO, 'About to submit job to %s with timeout %s' % (transfertool_obj, timeout))
# A eid is returned if the job is properly submitted otherwise an exception is raised
is_bulk = len(transfers) > 1
eid = None
start_time = time.time()
state_to_set = RequestState.SUBMISSION_FAILED
try:
record_counter('core.request.submit_transfer')
eid = transfertool_obj.submit(transfers, job_params, timeout)
state_to_set = RequestState.SUBMITTED
except DuplicateFileTransferSubmission:
if is_bulk:
raise
except (TransferToolTimeout, TransferToolWrongAnswer) as error:
logger(logging.ERROR, 'Failed to submit a job with error %s', str(error), exc_info=True)
except Exception as error:
logger(logging.ERROR, 'Failed to submit a job with error %s', str(error), exc_info=True)
# Keep the behavior from before the refactoring: in case of unexpected exception, only
# update request state on individual transfers, and do nothing for bulks.
# Don't know why it's like that.
#
# FIXME: shouldn't we always set the state to SUBMISSION_FAILED?
if is_bulk:
state_to_set = None
if eid is not None:
duration = time.time() - start_time
logger(logging.INFO, 'Submit job %s to %s in %s seconds' % (eid, transfertool_obj, duration))
record_timer('daemons.conveyor.{submitter}.submit_bulk_transfer.per_file', (time.time() - start_time) * 1000 / len(transfers) or 1, labels={'submitter': submitter})
record_counter('daemons.conveyor.{submitter}.submit_bulk_transfer', delta=len(transfers), labels={'submitter': submitter})
record_timer('daemons.conveyor.{submitter}.submit_bulk_transfer.files', len(transfers), labels={'submitter': submitter})
if state_to_set:
try:
transfer_core.set_transfers_state(transfers, state=state_to_set, external_host=transfertool_obj.external_host,
external_id=eid, submitted_at=datetime.datetime.utcnow(), logger=logger)
except Exception:
logger(logging.ERROR, 'Failed to register transfer state with error', exc_info=True)
if eid is not None:
# The job is still submitted in the file transfer service but the request is not updated.
# Possibility to have a double submission during the next cycle. Try to cancel the external request.
try:
logger(logging.INFO, 'Cancel transfer %s on %s', eid, transfertool_obj)
request.cancel_request_external_id(transfertool_obj, eid)
except Exception:
logger(logging.ERROR, 'Failed to cancel transfers %s on %s with error' % (eid, transfertool_obj), exc_info=True)
def submit_transfer(external_host, job, submitter='submitter', timeout=None, user_transfer_job=False, logger=logging.log, transfertool=TRANSFER_TOOL):
"""
Submit a transfer or staging request
:param external_host: FTS server to submit to.
:param job: Job dictionary.
:param submitter: Name of the submitting entity.
:param timeout: Timeout
:param user_transfer_job: Parameter for transfer with user credentials
:param logger: Optional decorated logger that can be passed from the calling daemons or servers.
"""
# Prepare submitting
xfers_ret = {}
try:
for t_file in job['files']:
file_metadata = t_file['metadata']
request_id = file_metadata['request_id']
log_str = 'PREPARING REQUEST %s DID %s:%s TO SUBMITTING STATE PREVIOUS %s FROM %s TO %s USING %s ' % (file_metadata['request_id'],
file_metadata['scope'],
file_metadata['name'],
file_metadata['previous_attempt_id'] if 'previous_attempt_id' in file_metadata else None,
t_file['sources'],
t_file['destinations'],
external_host)
xfers_ret[request_id] = {'state': RequestState.SUBMITTING, 'external_host': external_host, 'external_id': None, 'dest_url': t_file['destinations'][0]}
logger(logging.INFO, "%s", log_str)
xfers_ret[request_id]['file'] = t_file
logger(logging.DEBUG, 'Start to prepare transfer')
transfer_core.prepare_sources_for_transfers(xfers_ret)
logger(logging.DEBUG, 'Finished to prepare transfer')
except RequestNotFound as error:
logger(logging.ERROR, str(error))
return
except Exception:
logger(logging.ERROR, 'Failed to prepare requests %s state to SUBMITTING (Will not submit jobs but return directly) with error: %s' % (list(xfers_ret.keys())), exc_info=True)
return
# Prepare the dictionary for xfers results
xfers_ret = {}
for t_file in job['files']:
file_metadata = t_file['metadata']
request_id = file_metadata['request_id']
xfers_ret[request_id] = {'scope': file_metadata['scope'],
'name': file_metadata['name'],
'external_host': external_host,
'external_id': None,
'request_type': t_file.get('request_type', None),
'dst_rse': file_metadata.get('dst_rse', None),
'src_rse': file_metadata.get('src_rse', None),
'src_rse_id': file_metadata['src_rse_id'],
'metadata': file_metadata}
# Submit the job
try:
start_time = time.time()
logger(logging.INFO, 'About to submit job to %s with timeout %s' % (external_host, timeout))
# A eid is returned if the job is properly submitted otherwise an exception is raised
eid = transfer_core.submit_bulk_transfers(external_host,
files=job['files'],
transfertool=transfertool,
job_params=job['job_params'],
timeout=timeout,
user_transfer_job=user_transfer_job)
duration = time.time() - start_time
logger(logging.INFO, 'Submit job %s to %s in %s seconds' % (eid, external_host, duration))
record_timer('daemons.conveyor.%s.submit_bulk_transfer.per_file' % submitter, (time.time() - start_time) * 1000 / len(job['files']))
record_counter('daemons.conveyor.%s.submit_bulk_transfer' % submitter, len(job['files']))
record_timer('daemons.conveyor.%s.submit_bulk_transfer.files' % submitter, len(job['files']))
# Update all the requests to SUBMITTED and cancel the transfer job in case the update failed
try:
for t_file in job['files']:
file_metadata = t_file['metadata']
request_id = file_metadata['request_id']
xfers_ret[request_id]['state'] = RequestState.SUBMITTED
xfers_ret[request_id]['external_id'] = eid
logger(logging.INFO, 'COPYING REQUEST %s DID %s:%s USING %s with state(%s) with eid(%s)' % (file_metadata['request_id'], file_metadata['scope'], file_metadata['name'], external_host, RequestState.SUBMITTED, eid))
logger(logging.DEBUG, 'Start to bulk register transfer state for eid %s' % eid)
transfer_core.set_transfers_state(xfers_ret, datetime.datetime.utcnow())
logger(logging.DEBUG, 'Finished to register transfer state',)
except Exception:
logger(logging.ERROR, 'Failed to register transfer state with error', exc_info=True)
try:
logger(logging.INFO, 'Cancel transfer %s on %s', eid, external_host)
request.cancel_request_external_id(eid, external_host)
except Exception:
# The job is still submitted in the file transfer service but the request is not updated. Possibility to have a double submission during the next cycle
logger(logging.ERROR, 'Failed to cancel transfers %s on %s with error' % (eid, external_host), exc_info=True)
# This exception is raised if one job is already submitted for one file
except DuplicateFileTransferSubmission as error:
logger(logging.WARNING, 'Failed to submit a job because of duplicate file : %s', str(error))
logger(logging.INFO, 'Submitting files one by one')
try:
# In this loop we submit the jobs and update the requests state one by one
single_xfers_ret = {}
for t_file in job['files']:
single_xfers_ret = {}
single_xfers_ret[request_id] = xfers_ret[request_id]
file_metadata = t_file['metadata']
request_id = file_metadata['request_id']
start_time = time.time()
logger(logging.INFO, 'About to submit job to %s with timeout %s', external_host, timeout)
eid = transfer_core.submit_bulk_transfers(external_host,
files=[t_file],
transfertool=transfertool,
job_params=job['job_params'],
timeout=timeout,
user_transfer_job=user_transfer_job)
duration = time.time() - start_time
logger(logging.INFO, 'Submit job %s to %s in %s seconds' % (eid, external_host, duration))
record_timer('daemons.conveyor.%s.submit_bulk_transfer.per_file' % submitter, (time.time() - start_time) * 1000)
record_counter('daemons.conveyor.%s.submit_bulk_transfer' % submitter, 1)
record_timer('daemons.conveyor.%s.submit_bulk_transfer.files' % submitter, 1)
single_xfers_ret[request_id]['state'] = RequestState.SUBMITTED
single_xfers_ret[request_id]['external_id'] = eid
logger(logging.INFO, 'COPYING REQUEST %s DID %s:%s USING %s with state(%s) with eid(%s)' % (file_metadata['request_id'], file_metadata['scope'], file_metadata['name'], external_host, RequestState.SUBMITTED, eid))
try:
logger(logging.DEBUG, 'Start to register transfer state')
transfer_core.set_transfers_state(single_xfers_ret, datetime.datetime.utcnow())
logger(logging.DEBUG, 'Finished to register transfer state')
except Exception:
logger(logging.ERROR, 'Failed to register transfer state with error', exc_info=True)
try:
logger(logging.INFO, 'Cancel transfer %s on %s', eid, external_host)
request.cancel_request_external_id(eid, external_host)
except Exception:
logger(logging.ERROR, 'Failed to cancel transfers %s on %s with error' % (eid, external_host), exc_info=True)
except (DuplicateFileTransferSubmission, TransferToolTimeout, TransferToolWrongAnswer, Exception) as error:
request_id = single_xfers_ret.keys()[0]
single_xfers_ret[request_id]['state'] = RequestState.SUBMISSION_FAILED
logger(logging.ERROR, 'Cannot submit the job for request %s : %s', request_id, str(error))
try:
logger(logging.DEBUG, 'Update the transfer state to fail')
transfer_core.set_transfers_state(single_xfers_ret, datetime.datetime.utcnow())
logger(logging.DEBUG, 'Finished to register transfer state')
except Exception:
logger(logging.ERROR, 'Failed to register transfer state with error', exc_info=True)
# No need to cancel the job here
# The following exceptions are raised if the job failed to be submitted
except (TransferToolTimeout, TransferToolWrongAnswer) as error:
logger(logging.ERROR, str(error))
try:
for t_file in job['files']:
file_metadata = t_file['metadata']
request_id = file_metadata['request_id']
xfers_ret[request_id]['state'] = RequestState.SUBMISSION_FAILED
logger(logging.DEBUG, 'Start to register transfer state')
transfer_core.set_transfers_state(xfers_ret, datetime.datetime.utcnow())
logger(logging.DEBUG, 'Finished to register transfer state')
except Exception:
logger(logging.ERROR, 'Failed to register transfer state with error', exc_info=True)
# No need to cancel the job here
except Exception as error:
logger(logging.ERROR, 'Failed to submit a job with error %s', str(error), exc_info=True)
def submit_transfer(external_host,
job,
submitter='submitter',
process=0,
thread=0,
timeout=None,
user_transfer_job=False):
"""
Submit a transfer or staging request
:param external_host: FTS server to submit to.
:param job: Job dictionary.
:param submitter: Name of the submitting entity.
:param process: Process which submits.
:param thread: Thread which submits.
:param timeout: Timeout
"""
# prepare submitting
xfers_ret = {}
try:
for file in job['files']:
file_metadata = file['metadata']
request_id = file_metadata['request_id']
log_str = '%s:%s PREPARING REQUEST %s DID %s:%s TO SUBMITTING STATE PREVIOUS %s FROM %s TO %s USING %s ' % (
process, thread, file_metadata['request_id'],
file_metadata['scope'], file_metadata['name'],
file_metadata['previous_attempt_id']
if 'previous_attempt_id' in file_metadata else None,
file['sources'], file['destinations'], external_host)
xfers_ret[request_id] = {
'state': RequestState.SUBMITTING,
'external_host': external_host,
'external_id': None,
'dest_url': file['destinations'][0]
}
logging.info("%s" % (log_str))
xfers_ret[request_id]['file'] = file
logging.debug("%s:%s start to prepare transfer" % (process, thread))
transfer_core.prepare_sources_for_transfers(xfers_ret)
logging.debug("%s:%s finished to prepare transfer" % (process, thread))
except:
logging.error(
"%s:%s Failed to prepare requests %s state to SUBMITTING(Will not submit jobs but return directly) with error: %s"
%
(process, thread, list(xfers_ret.keys()), traceback.format_exc()))
return
# submit the job
eid = None
try:
ts = time.time()
logging.info("%s:%s About to submit job to %s with timeout %s" %
(process, thread, external_host, timeout))
eid = transfer_core.submit_bulk_transfers(
external_host,
files=job['files'],
transfertool='fts3',
job_params=job['job_params'],
timeout=timeout,
user_transfer_job=user_transfer_job)
duration = time.time() - ts
logging.info("%s:%s Submit job %s to %s in %s seconds" %
(process, thread, eid, external_host, duration))
record_timer(
'daemons.conveyor.%s.submit_bulk_transfer.per_file' % submitter,
(time.time() - ts) * 1000 / len(job['files']))
record_counter('daemons.conveyor.%s.submit_bulk_transfer' % submitter,
len(job['files']))
record_timer(
'daemons.conveyor.%s.submit_bulk_transfer.files' % submitter,
len(job['files']))
except Exception as error:
logging.error("Failed to submit a job with error %s: %s" %
(str(error), traceback.format_exc()))
# register transfer
xfers_ret = {}
try:
for file in job['files']:
file_metadata = file['metadata']
request_id = file_metadata['request_id']
log_str = '%s:%s COPYING REQUEST %s DID %s:%s USING %s' % (
process, thread, file_metadata['request_id'],
file_metadata['scope'], file_metadata['name'], external_host)
if eid:
xfers_ret[request_id] = {
'scope': file_metadata['scope'],
'name': file_metadata['name'],
'state': RequestState.SUBMITTED,
'external_host': external_host,
'external_id': eid,
'request_type': file.get('request_type', None),
'dst_rse': file_metadata.get('dst_rse', None),
'src_rse': file_metadata.get('src_rse', None),
'src_rse_id': file_metadata['src_rse_id'],
'metadata': file_metadata
}
log_str += 'with state(%s) with eid(%s)' % (
RequestState.SUBMITTED, eid)
logging.info("%s" % (log_str))
else:
xfers_ret[request_id] = {
'scope': file_metadata['scope'],
'name': file_metadata['name'],
'state': RequestState.SUBMISSION_FAILED,
'external_host': external_host,
'external_id': None,
'request_type': file.get('request_type', None),
'dst_rse': file_metadata.get('dst_rse', None),
'src_rse': file_metadata.get('src_rse', None),
'src_rse_id': file_metadata['src_rse_id'],
'metadata': file_metadata
}
log_str += 'with state(%s) with eid(%s)' % (
RequestState.SUBMISSION_FAILED, None)
logging.warn("%s" % (log_str))
logging.debug("%s:%s start to register transfer state" %
(process, thread))
transfer_core.set_transfers_state(xfers_ret,
datetime.datetime.utcnow())
logging.debug("%s:%s finished to register transfer state" %
(process, thread))
except:
logging.error(
"%s:%s Failed to register transfer state with error: %s" %
(process, thread, traceback.format_exc()))
try:
if eid:
logging.info("%s:%s Cancel transfer %s on %s" %
(process, thread, eid, external_host))
request.cancel_request_external_id(eid, external_host)
except:
logging.error(
"%s:%s Failed to cancel transfers %s on %s with error: %s" %
(process, thread, eid, external_host, traceback.format_exc()))
'name': file_metadata['name'],
'state': RequestState.SUBMISSION_FAILED,
'external_host': external_host,
'external_id': None,
'request_type': file.get('request_type', None),
'dst_rse': file_metadata.get('dst_rse', None),
'src_rse': file_metadata.get('src_rse', None),
'src_rse_id': file_metadata['src_rse_id'],
'metadata': file_metadata
}
log_str += 'with state(%s) with eid(%s)' % (
RequestState.SUBMISSION_FAILED, None)
logging.warn("%s" % (log_str))
logging.debug("%s:%s start to register transfer state" %
(process, thread))
transfer_core.set_transfers_state(xfers_ret,
datetime.datetime.utcnow())
logging.debug("%s:%s finished to register transfer state" %
(process, thread))
except:
logging.error(
"%s:%s Failed to register transfer state with error: %s" %
(process, thread, traceback.format_exc()))
try:
if eid:
logging.info("%s:%s Cancel transfer %s on %s" %
(process, thread, eid, external_host))
request.cancel_request_external_id(eid, external_host)
except:
logging.error(
"%s:%s Failed to cancel transfers %s on %s with error: %s" %
(process, thread, eid, external_host, traceback.format_exc()))
def submit_transfer(external_host,
job,
submitter='submitter',
logging_prepend_str='',
timeout=None,
user_transfer_job=False):
"""
Submit a transfer or staging request
:param external_host: FTS server to submit to.
:param job: Job dictionary.
:param submitter: Name of the submitting entity.
:param logging_prepend_str: String to prepend to the logging
:param timeout: Timeout
:param user_transfer_job: Parameter for transfer with user credentials
"""
prepend_str = ''
if logging_prepend_str:
prepend_str = logging_prepend_str
# prepare submitting
xfers_ret = {}
try:
for file in job['files']:
file_metadata = file['metadata']
request_id = file_metadata['request_id']
log_str = prepend_str + 'PREPARING REQUEST %s DID %s:%s TO SUBMITTING STATE PREVIOUS %s FROM %s TO %s USING %s ' % (
file_metadata['request_id'], file_metadata['scope'],
file_metadata['name'], file_metadata['previous_attempt_id']
if 'previous_attempt_id' in file_metadata else None,
file['sources'], file['destinations'], external_host)
xfers_ret[request_id] = {
'state': RequestState.SUBMITTING,
'external_host': external_host,
'external_id': None,
'dest_url': file['destinations'][0]
}
logging.info("%s" % (log_str))
xfers_ret[request_id]['file'] = file
logging.debug(prepend_str + 'Start to prepare transfer')
transfer_core.prepare_sources_for_transfers(xfers_ret)
logging.debug(prepend_str + 'Finished to prepare transfer')
except RequestNotFound as error:
logging.error(prepend_str + str(error))
return
except Exception:
logging.error(
prepend_str +
'Failed to prepare requests %s state to SUBMITTING (Will not submit jobs but return directly) with error: %s'
% (list(xfers_ret.keys()), traceback.format_exc()))
return
# submit the job
eid = None
try:
start_time = time.time()
logging.info(prepend_str +
'About to submit job to %s with timeout %s' %
(external_host, timeout))
eid = transfer_core.submit_bulk_transfers(
external_host,
files=job['files'],
transfertool='fts3',
job_params=job['job_params'],
timeout=timeout,
user_transfer_job=user_transfer_job)
duration = time.time() - start_time
logging.info(prepend_str + 'Submit job %s to %s in %s seconds' %
(eid, external_host, duration))
record_timer(
'daemons.conveyor.%s.submit_bulk_transfer.per_file' % submitter,
(time.time() - start_time) * 1000 / len(job['files']))
record_counter('daemons.conveyor.%s.submit_bulk_transfer' % submitter,
len(job['files']))
record_timer(
'daemons.conveyor.%s.submit_bulk_transfer.files' % submitter,
len(job['files']))
except (TransferToolTimeout, TransferToolWrongAnswer) as error:
logging.error(prepend_str + str(error))
except Exception as error:
logging.error(prepend_str +
'Failed to submit a job with error %s: %s' %
(str(error), traceback.format_exc()))
# register transfer
xfers_ret = {}
try:
for file in job['files']:
file_metadata = file['metadata']
request_id = file_metadata['request_id']
log_str = prepend_str + 'COPYING REQUEST %s DID %s:%s USING %s' % (
file_metadata['request_id'], file_metadata['scope'],
file_metadata['name'], external_host)
if eid:
xfers_ret[request_id] = {
'scope': file_metadata['scope'],
'name': file_metadata['name'],
'state': RequestState.SUBMITTED,
'external_host': external_host,
'external_id': eid,
'request_type': file.get('request_type', None),
'dst_rse': file_metadata.get('dst_rse', None),
'src_rse': file_metadata.get('src_rse', None),
'src_rse_id': file_metadata['src_rse_id'],
'metadata': file_metadata
}
log_str += ' with state(%s) with eid(%s)' % (
RequestState.SUBMITTED, eid)
logging.info("%s" % (log_str))
else:
xfers_ret[request_id] = {
'scope': file_metadata['scope'],
'name': file_metadata['name'],
'state': RequestState.SUBMISSION_FAILED,
'external_host': external_host,
'external_id': None,
'request_type': file.get('request_type', None),
'dst_rse': file_metadata.get('dst_rse', None),
'src_rse': file_metadata.get('src_rse', None),
'src_rse_id': file_metadata['src_rse_id'],
'metadata': file_metadata
}
log_str += ' with state(%s) with eid(%s)' % (
RequestState.SUBMISSION_FAILED, None)
logging.warn("%s" % (log_str))
logging.debug(prepend_str + 'Start to register transfer state')
transfer_core.set_transfers_state(xfers_ret,
datetime.datetime.utcnow())
logging.debug(prepend_str + 'Finished to register transfer state')
except Exception:
logging.error(prepend_str +
'Failed to register transfer state with error: %s' %
(traceback.format_exc()))
try:
if eid:
logging.info(prepend_str + 'Cancel transfer %s on %s' %
(eid, external_host))
request.cancel_request_external_id(eid, external_host)
except Exception:
logging.error(
prepend_str +
'Failed to cancel transfers %s on %s with error: %s' %
(eid, external_host, traceback.format_exc()))
