def report_on_it(dead, ara_reports_url,
gists, gist_mapping,
stdout_path, stderr_path):
started_at = timeutils.now()
last_report = timeutils.now()
last_gist_update = timeutils.now()
emitted_ara = False
while not dead.is_set():
now = timeutils.now()
secs_since_last_report = now - last_report
if secs_since_last_report >= self.report_period:
if not emitted_ara and ara_reports_url:
replier("Progress can be"
" watched at: %s" % ara_reports_url)
emitted_ara = True
if pbar is not None:
pbar.update(
'Your playbook has been running for'
' %s...' % utils.format_seconds(now - started_at))
last_report = now
secs_since_last_gist_update = now - last_gist_update
if secs_since_last_gist_update >= self.gist_update_period:
update_or_create_gist(gists, gist_mapping,
stdout_path, stderr_path)
last_gist_update = now
dead.wait(min([self.gist_update_period, self.report_period]))
def inner(*args, **kwargs):
t1 = timeutils.now()
t2 = None
try:
with lock(name,
lock_file_prefix,
external,
lock_path,
do_log=False,
semaphores=semaphores,
delay=delay,
fair=fair):
t2 = timeutils.now()
LOG.debug(
'Lock "%(name)s" acquired by "%(function)s" :: '
'waited %(wait_secs)0.3fs', {
'name': name,
'function': reflection.get_callable_name(f),
'wait_secs': (t2 - t1)
})
return f(*args, **kwargs)
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug(
'Lock "%(name)s" released by "%(function)s" :: held '
'%(held_secs)s', {
'name': name,
'function': reflection.get_callable_name(f),
'held_secs': held_secs
})
def _synchronized(f, *a, **k):
call_args = inspect.getcallargs(f, *a, **k)
call_args['f_name'] = f.__name__
lock = coordinator.get_lock(lock_name.format(**call_args))
t1 = timeutils.now()
t2 = None
try:
with lock(blocking):
t2 = timeutils.now()
LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
'waited %(wait_secs)0.3fs',
{'name': lock.name,
'function': f.__name__,
'wait_secs': (t2 - t1)})
return f(*a, **k)
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug('Lock "%(name)s" released by "%(function)s" :: held '
'%(held_secs)s',
{'name': lock.name,
'function': f.__name__,
'held_secs': held_secs})
def _synchronized(f, *a, **k):
call_args = inspect.getcallargs(f, *a, **k)
call_args['f_name'] = f.__name__
lock = Lock(lock_name, call_args, coordinator)
t1 = timeutils.now()
t2 = None
try:
with lock(blocking):
t2 = timeutils.now()
LOG.debug(
'Lock "%(name)s" acquired by "%(function)s" :: '
'waited %(wait_secs)0.3fs', {
'name': lock.name,
'function': f.__name__,
'wait_secs': (t2 - t1)
})
return f(*a, **k)
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug(
'Lock "%(name)s" released by "%(function)s" :: held '
'%(held_secs)s', {
'name': lock.name,
'function': f.__name__,
'held_secs': held_secs
})
def _synchronized(f, *a, **k):
if six.PY2:
# pylint: disable=deprecated-method
call_args = inspect.getcallargs(f, *a, **k)
else:
sig = inspect.signature(f).bind(*a, **k)
sig.apply_defaults()
call_args = sig.arguments
call_args['f_name'] = f.__name__
lock_format_name = lock_name.format(**call_args)
t1 = timeutils.now()
t2 = None
try:
with lockutils.lock(lock_format_name):
t2 = timeutils.now()
LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
'waited %(wait_secs)0.3fs',
{'name': lock_format_name,
'function': f.__name__,
'wait_secs': (t2 - t1)})
return f(*a, **k)
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug('Lock "%(name)s" released by "%(function)s" :: held '
'%(held_secs)s',
{'name': lock_format_name,
'function': f.__name__,
'held_secs': held_secs})
def inner(*args, **kwargs):
t1 = timeutils.now()
t2 = None
gotten = True
try:
with lock(name, lock_file_prefix, external, lock_path,
do_log=False, semaphores=semaphores, delay=delay,
fair=fair, blocking=blocking):
t2 = timeutils.now()
LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
'waited %(wait_secs)0.3fs',
{'name': name,
'function': reflection.get_callable_name(f),
'wait_secs': (t2 - t1)})
return f(*args, **kwargs)
except AcquireLockFailedException:
gotten = False
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug('Lock "%(name)s" "%(gotten)s" by "%(function)s" ::'
' held %(held_secs)s',
{'name': name,
'gotten': 'released' if gotten else 'unacquired',
'function': reflection.get_callable_name(f),
'held_secs': held_secs})
def inner(*args, **kwargs):
t1 = timeutils.now()
t2 = None
try:
with lock(name, lock_file_prefix, external, lock_path,
do_log=False, semaphores=semaphores, delay=delay,
fair=fair):
t2 = timeutils.now()
LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
'waited %(wait_secs)0.3fs',
{'name': name,
'function': reflection.get_callable_name(f),
'wait_secs': (t2 - t1)})
return f(*args, **kwargs)
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug('Lock "%(name)s" released by "%(function)s" :: held '
'%(held_secs)s',
{'name': name,
'function': reflection.get_callable_name(f),
'held_secs': held_secs})
def exc_retrier_sequence(self, exc_id=None,
exc_count=None, before_timestamp_calls=(),
after_timestamp_calls=()):
self.exception_to_raise().AndReturn(
Exception('unexpected %d' % exc_id))
# Timestamp calls that happen before the logging is possibly triggered.
for timestamp in before_timestamp_calls:
timeutils.now().AndReturn(timestamp)
if exc_count != 0:
logging.exception(mox.In(
'Unexpected exception occurred %d time(s)' % exc_count))
# Timestamp calls that happen after the logging is possibly triggered.
for timestamp in after_timestamp_calls:
timeutils.now().AndReturn(timestamp)
def exc_retrier_sequence(self, exc_id=None,
exc_count=None, before_timestamp_calls=(),
after_timestamp_calls=()):
self.exception_to_raise().AndReturn(
Exception('unexpected %d' % exc_id))
# Timestamp calls that happen before the logging is possibly triggered.
for timestamp in before_timestamp_calls:
timeutils.now().AndReturn(timestamp)
if exc_count != 0:
logging.exception(mox.In(
'Unexpected exception occurred %d time(s)' % exc_count))
# Timestamp calls that happen after the logging is possibly triggered.
for timestamp in after_timestamp_calls:
timeutils.now().AndReturn(timestamp)
def _get_dp_by_dpid(self, dpid_int):
"""Get os-ken datapath object for the switch."""
timeout_sec = cfg.CONF.OVS.of_connect_timeout
start_time = timeutils.now()
while True:
dp = ofctl_api.get_datapath(self._app, dpid_int)
if dp is not None:
break
# The switch has not established a connection to us; retry again
# until timeout.
if timeutils.now() > start_time + timeout_sec:
m = _("Switch connection timeout")
LOG.error(m)
# NOTE(yamamoto): use RuntimeError for compat with ovs_lib
raise RuntimeError(m)
return dp
def _go_no_go(self):
now = timeutils.now()
if self.last_sent is None:
return now, True
if (now - self.last_sent) >= self.EMIT_PERIOD:
return now, True
return now, False
def _publish_request(self, request, worker):
"""Publish request to a given topic."""
LOG.debug(
"Submitting execution of '%s' to worker '%s' (expecting"
" response identified by reply_to=%s and"
" correlation_id=%s) - waited %0.3f seconds to"
" get published", request, worker, self._uuid, request.uuid,
timeutils.now() - request.created_on)
try:
self._proxy.publish(request,
worker.topic,
reply_to=self._uuid,
correlation_id=request.uuid)
except Exception:
with misc.capture_failure() as failure:
LOG.critical(
"Failed to submit '%s' (transitioning it to"
" %s)",
request,
pr.FAILURE,
exc_info=True)
if request.transition_and_log_error(pr.FAILURE, logger=LOG):
with self._ongoing_requests_lock:
del self._ongoing_requests[request.uuid]
request.set_result(failure)
def _execute(self, action, file_path):
self.last_status = timeutils.now()
if action.image_status == "deleted":
raise exception.ImportTaskError("Image has been deleted, aborting"
" import.")
try:
action.set_image_data(file_path or self.uri,
self.task_id,
backend=self.backend,
set_active=self.set_active,
callback=self._status_callback)
# NOTE(yebinama): set_image_data catches Exception and raises from
# them. Can't be more specific on exceptions catched.
except Exception:
if self.all_stores_must_succeed:
raise
msg = (_("%(task_id)s of %(task_type)s failed but since "
"all_stores_must_succeed is set to false, continue.") % {
'task_id': self.task_id,
'task_type': self.task_type
})
LOG.warning(msg)
if self.backend is not None:
action.add_failed_stores([self.backend])
if self.backend is not None:
action.remove_importing_stores([self.backend])
def clean(self):
"""Cleans out any dead/expired/not responding workers.
Returns how many workers were removed.
"""
if (not self._workers or
(self._worker_expiry is None or self._worker_expiry <= 0)):
return 0
dead_workers = {}
with self._cond:
now = timeutils.now()
for topic, worker in six.iteritems(self._workers):
if worker.last_seen is None:
continue
secs_since_last_seen = max(0, now - worker.last_seen)
if secs_since_last_seen >= self._worker_expiry:
dead_workers[topic] = (worker, secs_since_last_seen)
for topic in six.iterkeys(dead_workers):
self._workers.pop(topic)
if dead_workers:
self._cond.notify_all()
if dead_workers and LOG.isEnabledFor(logging.INFO):
for worker, secs_since_last_seen in six.itervalues(dead_workers):
LOG.info("Removed worker '%s' as it has not responded to"
" notification requests in %0.3f seconds",
worker, secs_since_last_seen)
return len(dead_workers)
def clean(self):
"""Cleans out any dead/expired/not responding workers.
Returns how many workers were removed.
"""
if (not self._workers
or (self._worker_expiry is None or self._worker_expiry <= 0)):
return 0
dead_workers = {}
with self._cond:
now = timeutils.now()
for topic, worker in six.iteritems(self._workers):
if worker.last_seen is None:
continue
secs_since_last_seen = max(0, now - worker.last_seen)
if secs_since_last_seen >= self._worker_expiry:
dead_workers[topic] = (worker, secs_since_last_seen)
for topic in six.iterkeys(dead_workers):
self._workers.pop(topic)
if dead_workers:
self._cond.notify_all()
if dead_workers and LOG.isEnabledFor(logging.INFO):
for worker, secs_since_last_seen in six.itervalues(dead_workers):
LOG.info(
"Removed worker '%s' as it has not responded to"
" notification requests in %0.3f seconds", worker,
secs_since_last_seen)
return len(dead_workers)
def _get_dp_by_dpid(self, dpid_int):
"""Get Ryu datapath object for the switch."""
timeout_sec = cfg.CONF.OVS.of_connect_timeout
start_time = timeutils.now()
while True:
dp = ofctl_api.get_datapath(self._app, dpid_int)
if dp is not None:
break
# The switch has not established a connection to us.
# Wait for a little.
if timeutils.now() > start_time + timeout_sec:
m = _("Switch connection timeout")
LOG.error(m)
# NOTE(yamamoto): use RuntimeError for compat with ovs_lib
raise RuntimeError(m)
eventlet.sleep(1)
return dp
def _get_dp_by_dpid(self, dpid_int):
"""Get Ryu datapath object for the switch."""
timeout_sec = constants.OF_CONNECT_TIMEOUT
start_time = timeutils.now()
while True:
dp = ofctl_api.get_datapath(self._app, dpid_int)
if dp is not None:
break
# The switch has not established a connection to us.
# Wait for a little.
if timeutils.now() > start_time + timeout_sec:
m = "Switch connection timeout"
LOG.error(m)
# NOTE(yamamoto): use RuntimeError for compat with ovs_lib
raise RuntimeError(m)
eventlet.sleep(1)
return dp
def _get_dp_by_dpid(self, dpid_int):
LOG.info('%s(): caller(): %s', log_utils.get_fname(1),
log_utils.get_fname(2))
"""Get os-ken datapath object for the switch."""
timeout_sec = cfg.CONF.OVS.of_connect_timeout
start_time = timeutils.now()
while True:
dp = ofctl_api.get_datapath(self._app, dpid_int)
if dp is not None:
break
# The switch has not established a connection to us.
# Wait for a little.
if timeutils.now() > start_time + timeout_sec:
m = _("Switch connection timeout")
LOG.error(m)
# NOTE(yamamoto): use RuntimeError for compat with ovs_lib
raise RuntimeError(m)
eventlet.sleep(1)
return dp
def _status_callback(self, action, chunk_bytes, total_bytes):
# NOTE(danms): Only log status every five minutes
if timeutils.now() - self.last_status > 300:
LOG.debug('Image import %(image_id)s copied %(copied)i MiB',
{'image_id': action.image_id,
'copied': total_bytes // units.Mi})
self.last_status = timeutils.now()
task = script_utils.get_task(self.task_repo, self.task_id)
if task is None:
LOG.error(
'Status callback for task %(task)s found no task object!',
{'task': self.task_id})
raise exception.TaskNotFound(self.task_id)
if task.status != 'processing':
LOG.error('Task %(task)s expected "processing" status, '
'but found "%(status)s"; aborting.')
raise exception.TaskAbortedError()
task.message = _('Copied %i MiB') % (total_bytes // units.Mi)
self.task_repo.save(task)
def _synchronized(f, *a, **k) -> Callable:
call_args = inspect.getcallargs(f, *a, **k)
call_args['f_name'] = f.__name__
lock = coordinator.get_lock(lock_name.format(**call_args))
name = utils.convert_str(lock.name)
f_name = f.__name__
t1 = timeutils.now()
t2 = None
try:
LOG.debug(f'Acquiring lock "{name}" by "{f_name}"')
with lock(blocking):
t2 = timeutils.now()
LOG.debug(f'Lock "{name}" acquired by "{f_name}" :: '
f'waited {t2 - t1:0.3f}s')
return f(*a, **k)
finally:
t3 = timeutils.now()
if t2 is None:
held_secs = "N/A"
else:
held_secs = "%0.3fs" % (t3 - t2)
LOG.debug(
f'Lock "{name}" released by "{f_name}" :: held {held_secs}')
def process_response(self, data, message):
"""Process notify message sent from remote side."""
LOG.debug("Started processing notify response message '%s'",
ku.DelayedPretty(message))
response = pr.Notify(**data)
LOG.debug("Extracted notify response '%s'", response)
with self._cond:
worker, new_or_updated = self._add(response.topic, response.tasks)
if new_or_updated:
LOG.debug(
"Updated worker '%s' (%s total workers are"
" currently known)", worker, self.total_workers)
self._cond.notify_all()
worker.last_seen = timeutils.now()
self._messages_processed += 1
def process_response(self, data, message):
"""Process notify message sent from remote side."""
LOG.debug("Started processing notify response message '%s'",
ku.DelayedPretty(message))
response = pr.Notify(**data)
LOG.debug("Extracted notify response '%s'", response)
with self._cond:
worker, new_or_updated = self._add(response.topic,
response.tasks)
if new_or_updated:
LOG.debug("Updated worker '%s' (%s total workers are"
" currently known)", worker, self.total_workers)
self._cond.notify_all()
worker.last_seen = timeutils.now()
self._messages_processed += 1
def __init__(self, task, uuid, action,
arguments, timeout=REQUEST_TIMEOUT, result=NO_RESULT,
failures=None):
self._action = action
self._event = ACTION_TO_EVENT[action]
self._arguments = arguments
self._result = result
self._failures = failures
self._watch = timeutils.StopWatch(duration=timeout).start()
self._lock = threading.Lock()
self.state = WAITING
self.task = task
self.uuid = uuid
self.created_on = timeutils.now()
self.future = futurist.Future()
self.future.atom = task
def process_response(self, data, message):
"""Process notify message (response) sent from remote side.
NOTE(harlowja): the message content should already have had
basic validation performed on it...
"""
LOG.debug("Started processing notify response message '%s'",
ku.DelayedPretty(message))
response = pr.Notify(**data)
LOG.debug("Extracted notify response '%s'", response)
with self._cond:
worker, new_or_updated = self._add(response.topic, response.tasks)
if new_or_updated:
LOG.debug(
"Received notification about worker '%s' (%s"
" total workers are currently known)", worker,
self.available_workers)
self._cond.notify_all()
worker.last_seen = timeutils.now()
def _publish_request(self, request, worker):
"""Publish request to a given topic."""
LOG.debug("Submitting execution of '%s' to worker '%s' (expecting"
" response identified by reply_to=%s and"
" correlation_id=%s) - waited %0.3f seconds to"
" get published", request, worker, self._uuid,
request.uuid, timeutils.now() - request.created_on)
try:
self._proxy.publish(request, worker.topic,
reply_to=self._uuid,
correlation_id=request.uuid)
except Exception:
with misc.capture_failure() as failure:
LOG.critical("Failed to submit '%s' (transitioning it to"
" %s)", request, pr.FAILURE, exc_info=True)
if request.transition_and_log_error(pr.FAILURE, logger=LOG):
with self._ongoing_requests_lock:
del self._ongoing_requests[request.uuid]
request.set_result(failure)
def set_project_name_to_objects(request, objects):
global PROJECTS, TIME
try:
# NOTE(vponomaryov): we will use saved values making lots of requests
# in short period of time. 'memoized' is not suitable here
now = timeutils.now()
if TIME is None:
TIME = now
if not PROJECTS or now > TIME + 20:
projects, has_more = keystone.tenant_list(request)
PROJECTS = {t.id: t for t in projects}
TIME = now
except Exception:
msg = _('Unable to retrieve list of projects.')
exceptions.handle(request, msg)
for obj in objects:
project_id = getattr(obj, "project_id", None)
project = PROJECTS.get(project_id, None)
obj.project_name = getattr(project, "name", None)
def set_project_name_to_objects(request, objects):
global PROJECTS, TIME
try:
# NOTE(vponomaryov): we will use saved values making lots of requests
# in short period of time. 'memoized' is not suitable here
now = timeutils.now()
if TIME is None:
TIME = now
if not PROJECTS or now > TIME + 20:
projects, has_more = keystone.tenant_list(request)
PROJECTS = {t.id: t for t in projects}
TIME = now
except Exception:
msg = _('Unable to retrieve list of projects.')
exceptions.handle(request, msg)
for obj in objects:
project_id = getattr(obj, "project_id", None)
project = PROJECTS.get(project_id, None)
obj.project_name = getattr(project, "name", None)
def __init__(self,
task,
uuid,
action,
arguments,
timeout=REQUEST_TIMEOUT,
result=NO_RESULT,
failures=None):
self._action = action
self._event = ACTION_TO_EVENT[action]
self._arguments = arguments
self._result = result
self._failures = failures
self._watch = timeutils.StopWatch(duration=timeout).start()
self._lock = threading.Lock()
self.state = WAITING
self.task = task
self.uuid = uuid
self.created_on = timeutils.now()
self.future = futurist.Future()
self.future.atom = task
def _handle_expired_request(request):
"""Handle a expired request.
When a request has expired it is removed from the ongoing requests
dictionary and a ``RequestTimeout`` exception is set as a
request result.
"""
if request.transition_and_log_error(pr.FAILURE, logger=LOG):
# Raise an exception (and then catch it) so we get a nice
# traceback that the request will get instead of it getting
# just an exception with no traceback...
try:
request_age = timeutils.now() - request.created_on
raise exc.RequestTimeout(
"Request '%s' has expired after waiting for %0.2f"
" seconds for it to transition out of (%s) states"
% (request, request_age, ", ".join(pr.WAITING_STATES)))
except exc.RequestTimeout:
with misc.capture_failure() as failure:
LOG.debug(failure.exception_str)
request.set_result(failure)
return True
return False
def _watch(self, job_name, build, jenkins_client, job=None):
replier = self.message.reply_text
replier = functools.partial(replier, threaded=True, prefixed=False)
if job is None:
replier("Locating job `%s`, please wait..." % job_name)
job = jenkins_client.get_job(job_name)
if job is None:
replier("Job `%s` was not found!" % job_name)
return
if isinstance(build, six.string_types):
build = int(build)
if isinstance(build, six.integer_types):
build_num = build
replier("Locating build `%s`, please wait..." % build_num)
build = job.get_build(build)
if build is None:
replier("Job `%s` build `%s` was"
" not found!" % (job_name, build_num))
return
build_num = build.number
replier("Watching initiated for"
" job `%s` build `%s`" % (job_name, build_num))
max_build_wait = None
try:
max_build_wait = self.config.jenkins.max_build_wait
except AttributeError:
pass
report_bar = self.message.make_manual_progress_bar()
with timeutils.StopWatch(duration=max_build_wait) as watch:
# At this point we can be cancelled safely, so allow that
# to happen (or at least allow someone to try it).
self.job = job
self.build = build
if build.is_running():
still_running = True
build_eta = build.get_eta()
if build_eta != float("inf"):
eta_sec = max(0, build_eta - watch.elapsed())
eta_text = "%0.2fs/%0.2fm" % (eta_sec, eta_sec / 60.0)
report_bar.update("Estimated time to completion is %s" %
eta_text)
else:
report_bar.update("Estimated time to"
" completion is unknown.")
last_build_fetch = timeutils.now()
while still_running:
if watch.expired():
replier("Timed out (waited %0.2f seconds) while"
" checking your build." % watch.elapsed())
return
self.dead.wait(self.poll_delay)
if self.dead.is_set():
replier("I have been terminated, please"
" check the jenkins job url for the"
" final result.")
return
now = timeutils.now()
since_last_build_info = now - last_build_fetch
if since_last_build_info > self.build_info_delay:
build.poll()
if build.is_running():
build_eta = build.get_eta()
if build_eta != float("inf"):
eta_sec = build_eta - watch.elapsed()
eta_sec_min = eta_sec / 60.0
if eta_sec >= 0:
eta_text = "%0.2fs/%0.2fm" % (eta_sec,
eta_sec_min)
report_bar.update("Estimated time to"
" completion is %s" %
eta_text)
else:
eta_sec = eta_sec * -1
eta_sec_min = eta_sec_min * -1
eta_text = "%0.2fs/%0.2fm" % (eta_sec,
eta_sec_min)
report_bar.update(
"Job is %s over estimated time"
" to completion" % eta_text)
else:
report_bar.update("Estimated time to"
" completion is unknown.")
else:
still_running = False
since_last_build_info = now
# Force getting the newest data...
build.poll()
result = build.get_result()
# Try to get some console log (if this fails it doesn't really matter)
result_dict = None
console_out_pretty = None
try:
console_out = build.get_console()
console_out_pretty = _format_build_console(
console_out, line_limit=CONSOLE_LINES)
result_dict = _console_get_result_dict(console_out)
except Exception:
LOG.warn("Failed getting build console for '%s'",
build,
exc_info=True)
if not result:
result = "UNKNOWN"
replier("Your jenkins job finished with result `%s`" % result)
if result_dict:
replier(_format_result_dict(result_dict))
if result == "FAILURE" and console_out_pretty:
replier(console_out_pretty)
return result_dict
