# Copyright 2015 gRPC authors. # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. # You may obtain a copy of the License at # # http://www.apache.org/licenses/LICENSE-2.0 # # Unless required by applicable law or agreed to in writing, software # distributed under the License is distributed on an "AS IS" BASIS, # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. """Run a group of subprocesses and then finish.""" import logging import multiprocessing import os import platform import re import signal import subprocess import sys import tempfile import time import errno # cpu cost measurement measure_cpu_costs = False _DEFAULT_MAX_JOBS = 16 * multiprocessing.cpu_count() # Maximum number of bytes of job's stdout that will be stored in the result. # Only last N bytes of stdout will be kept if the actual output longer. _MAX_RESULT_SIZE = 64 * 1024 # NOTE: If you change this, please make sure to test reviewing the # github PR with http://reviewable.io, which is known to add UTF-8 # characters to the PR description, which leak into the environment here # and cause failures. def strip_non_ascii_chars(s): return ''.join(c for c in s if ord(c) < 128) def sanitized_environment(env): sanitized = {} for key, value in env.items(): sanitized[strip_non_ascii_chars(key)] = strip_non_ascii_chars(value) return sanitized def platform_string(): if platform.system() == 'Windows': return 'windows' elif platform.system()[:7] == 'MSYS_NT': return 'windows' elif platform.system() == 'Darwin': return 'mac' elif platform.system() == 'Linux': return 'linux' else: return 'posix' # setup a signal handler so that signal.pause registers 'something' # when a child finishes # not using futures and threading to avoid a dependency on subprocess32 if platform_string() == 'windows': pass else: def alarm_handler(unused_signum, unused_frame): pass signal.signal(signal.SIGCHLD, lambda unused_signum, unused_frame: None) signal.signal(signal.SIGALRM, alarm_handler) _SUCCESS = object() _FAILURE = object() _RUNNING = object() _KILLED = object() _COLORS = { 'red': [31, 0], 'green': [32, 0], 'yellow': [33, 0], 'lightgray': [37, 0], 'gray': [30, 1], 'purple': [35, 0], 'cyan': [36, 0] } _BEGINNING_OF_LINE = '\x1b[0G' _CLEAR_LINE = '\x1b[2K' _TAG_COLOR = { 'FAILED': 'red', 'FLAKE': 'purple', 'TIMEOUT_FLAKE': 'purple', 'WARNING': 'yellow', 'TIMEOUT': 'red', 'PASSED': 'green', 'START': 'gray', 'WAITING': 'yellow', 'SUCCESS': 'green', 'IDLE': 'gray', 'SKIPPED': 'cyan' } _FORMAT = '%(asctime)-15s %(message)s' logging.basicConfig(level=logging.INFO, format=_FORMAT) def eintr_be_gone(fn): """Run fn until it doesn't stop because of EINTR""" while True: try: return fn() except IOError as e: if e.errno != errno.EINTR: raise def message(tag, msg, explanatory_text=None, do_newline=False): if message.old_tag == tag and message.old_msg == msg and not explanatory_text: return message.old_tag = tag message.old_msg = msg while True: try: if platform_string() == 'windows' or not sys.stdout.isatty(): if explanatory_text: logging.info(explanatory_text) logging.info('%s: %s', tag, msg) else: sys.stdout.write( '%s%s%s\x1b[%d;%dm%s\x1b[0m: %s%s' % (_BEGINNING_OF_LINE, _CLEAR_LINE, '\n%s' % explanatory_text if explanatory_text is not None else '', _COLORS[_TAG_COLOR[tag]][1], _COLORS[_TAG_COLOR[tag]][0], tag, msg, '\n' if do_newline or explanatory_text is not None else '')) sys.stdout.flush() return except IOError as e: if e.errno != errno.EINTR: raise message.old_tag = '' message.old_msg = '' def which(filename): if '/' in filename: return filename for path in os.environ['PATH'].split(os.pathsep): if os.path.exists(os.path.join(path, filename)): return os.path.join(path, filename) raise Exception('%s not found' % filename) class JobSpec(object): """Specifies what to run for a job.""" def __init__(self, cmdline, shortname=None, environ=None, cwd=None, shell=False, timeout_seconds=5 * 60, flake_retries=0, timeout_retries=0, kill_handler=None, cpu_cost=1.0, verbose_success=False, logfilename=None): """ Arguments: cmdline: a list of arguments to pass as the command line environ: a dictionary of environment variables to set in the child process kill_handler: a handler that will be called whenever job.kill() is invoked cpu_cost: number of cores per second this job needs logfilename: use given file to store job's output, rather than using a temporary file """ if environ is None: environ = {} self.cmdline = cmdline self.environ = environ self.shortname = cmdline[0] if shortname is None else shortname self.cwd = cwd self.shell = shell self.timeout_seconds = timeout_seconds self.flake_retries = flake_retries self.timeout_retries = timeout_retries self.kill_handler = kill_handler self.cpu_cost = cpu_cost self.verbose_success = verbose_success self.logfilename = logfilename if self.logfilename and self.flake_retries != 0 and self.timeout_retries != 0: # Forbidden to avoid overwriting the test log when retrying. raise Exception( 'Cannot use custom logfile when retries are enabled') def identity(self): return '%r %r' % (self.cmdline, self.environ) def __hash__(self): return hash(self.identity()) def __cmp__(self, other): return self.identity() == other.identity() def __repr__(self): return 'JobSpec(shortname=%s, cmdline=%s)' % (self.shortname, self.cmdline) def __str__(self): return '%s: %s %s' % (self.shortname, ' '.join( '%s=%s' % kv for kv in self.environ.items()), ' '.join(self.cmdline)) class JobResult(object): def __init__(self): self.state = 'UNKNOWN' self.returncode = -1 self.elapsed_time = 0 self.num_failures = 0 self.retries = 0 self.message = '' self.cpu_estimated = 1 self.cpu_measured = 1 def read_from_start(f): f.seek(0) return f.read() class Job(object): """Manages one job.""" def __init__(self, spec, newline_on_success, travis, add_env, quiet_success=False): self._spec = spec self._newline_on_success = newline_on_success self._travis = travis self._add_env = add_env.copy() self._retries = 0 self._timeout_retries = 0 self._suppress_failure_message = False self._quiet_success = quiet_success if not self._quiet_success: message('START', spec.shortname, do_newline=self._travis) self.result = JobResult() self.start() def GetSpec(self): return self._spec def start(self): if self._spec.logfilename: # make sure the log directory exists logfile_dir = os.path.dirname( os.path.abspath(self._spec.logfilename)) if not os.path.exists(logfile_dir): os.makedirs(logfile_dir) self._logfile = open(self._spec.logfilename, 'w+') else: self._logfile = tempfile.TemporaryFile() env = dict(os.environ) env.update(self._spec.environ) env.update(self._add_env) env = sanitized_environment(env) self._start = time.time() cmdline = self._spec.cmdline # The Unix time command is finicky when used with MSBuild, so we don't use it # with jobs that run MSBuild. global measure_cpu_costs if measure_cpu_costs and not 'vsprojects\\build' in cmdline[0]: cmdline = ['time', '-p'] + cmdline else: measure_cpu_costs = False try_start = lambda: subprocess.Popen(args=cmdline, stderr=subprocess.STDOUT, stdout=self._logfile, cwd=self._spec.cwd, shell=self._spec.shell, env=env) delay = 0.3 for i in range(0, 4): try: self._process = try_start() break except OSError: message('WARNING', 'Failed to start %s, retrying in %f seconds' % (self._spec.shortname, delay)) time.sleep(delay) delay *= 2 else: self._process = try_start() self._state = _RUNNING def state(self): """Poll current state of the job. Prints messages at completion.""" def stdout(self=self): stdout = read_from_start(self._logfile) self.result.message = stdout[-_MAX_RESULT_SIZE:] return stdout if self._state == _RUNNING and self._process.poll() is not None: elapsed = time.time() - self._start self.result.elapsed_time = elapsed if self._process.returncode != 0: if self._retries < self._spec.flake_retries: message( 'FLAKE', '%s [ret=%d, pid=%d]' % (self._spec.shortname, self._process.returncode, self._process.pid), stdout(), do_newline=True) self._retries += 1 self.result.num_failures += 1 self.result.retries = self._timeout_retries + self._retries # NOTE: job is restarted regardless of jobset's max_time setting self.start() else: self._state = _FAILURE if not self._suppress_failure_message: message( 'FAILED', '%s [ret=%d, pid=%d, time=%.1fsec]' % (self._spec.shortname, self._process.returncode, self._process.pid, elapsed), stdout(), do_newline=True) self.result.state = 'FAILED' self.result.num_failures += 1 self.result.returncode = self._process.returncode else: self._state = _SUCCESS measurement = '' if measure_cpu_costs: m = re.search( r'real\s+([0-9.]+)\nuser\s+([0-9.]+)\nsys\s+([0-9.]+)', stdout()) real = float(m.group(1)) user = float(m.group(2)) sys = float(m.group(3)) if real > 0.5: cores = (user + sys) / real self.result.cpu_measured = float('%.01f' % cores) self.result.cpu_estimated = float( '%.01f' % self._spec.cpu_cost) measurement = '; cpu_cost=%.01f; estimated=%.01f' % ( self.result.cpu_measured, self.result.cpu_estimated) if not self._quiet_success: message( 'PASSED', '%s [time=%.1fsec, retries=%d:%d%s]' % (self._spec.shortname, elapsed, self._retries, self._timeout_retries, measurement), stdout() if self._spec.verbose_success else None, do_newline=self._newline_on_success or self._travis) self.result.state = 'PASSED' elif (self._state == _RUNNING and self._spec.timeout_seconds is not None and time.time() - self._start > self._spec.timeout_seconds): elapsed = time.time() - self._start self.result.elapsed_time = elapsed if self._timeout_retries < self._spec.timeout_retries: message( 'TIMEOUT_FLAKE', '%s [pid=%d]' % (self._spec.shortname, self._process.pid), stdout(), do_newline=True) self._timeout_retries += 1 self.result.num_failures += 1 self.result.retries = self._timeout_retries + self._retries if self._spec.kill_handler: self._spec.kill_handler(self) self._process.terminate() # NOTE: job is restarted regardless of jobset's max_time setting self.start() else: message( 'TIMEOUT', '%s [pid=%d, time=%.1fsec]' % (self._spec.shortname, self._process.pid, elapsed), stdout(), do_newline=True) self.kill() self.result.state = 'TIMEOUT' self.result.num_failures += 1 return self._state def kill(self): if self._state == _RUNNING: self._state = _KILLED if self._spec.kill_handler: self._spec.kill_handler(self) self._process.terminate() def suppress_failure_message(self): self._suppress_failure_message = True class Jobset(object): """Manages one run of jobs.""" def __init__(self, check_cancelled, maxjobs, maxjobs_cpu_agnostic, newline_on_success, travis, stop_on_failure, add_env, quiet_success, max_time): self._running = set() self._check_cancelled = check_cancelled self._cancelled = False self._failures = 0 self._completed = 0 self._maxjobs = maxjobs self._maxjobs_cpu_agnostic = maxjobs_cpu_agnostic self._newline_on_success = newline_on_success self._travis = travis self._stop_on_failure = stop_on_failure self._add_env = add_env self._quiet_success = quiet_success self._max_time = max_time self.resultset = {} self._remaining = None self._start_time = time.time() def set_remaining(self, remaining): self._remaining = remaining def get_num_failures(self): return self._failures def cpu_cost(self): c = 0 for job in self._running: c += job._spec.cpu_cost return c def start(self, spec): """Start a job. Return True on success, False on failure.""" while True: if self._max_time > 0 and time.time( ) - self._start_time > self._max_time: skipped_job_result = JobResult() skipped_job_result.state = 'SKIPPED' message('SKIPPED', spec.shortname, do_newline=True) self.resultset[spec.shortname] = [skipped_job_result] return True if self.cancelled(): return False current_cpu_cost = self.cpu_cost() if current_cpu_cost == 0: break if current_cpu_cost + spec.cpu_cost <= self._maxjobs: if len(self._running) < self._maxjobs_cpu_agnostic: break self.reap(spec.shortname, spec.cpu_cost) if self.cancelled(): return False job = Job(spec, self._newline_on_success, self._travis, self._add_env, self._quiet_success) self._running.add(job) if job.GetSpec().shortname not in self.resultset: self.resultset[job.GetSpec().shortname] = [] return True def reap(self, waiting_for=None, waiting_for_cost=None): """Collect the dead jobs.""" while self._running: dead = set() for job in self._running: st = eintr_be_gone(lambda: job.state()) if st == _RUNNING: continue if st == _FAILURE or st == _KILLED: self._failures += 1 if self._stop_on_failure: self._cancelled = True for job in self._running: job.kill() dead.add(job) break for job in dead: self._completed += 1 if not self._quiet_success or job.result.state != 'PASSED': self.resultset[job.GetSpec().shortname].append(job.result) self._running.remove(job) if dead: return if not self._travis and platform_string() != 'windows': rstr = '' if self._remaining is None else '%d queued, ' % self._remaining if self._remaining is not None and self._completed > 0: now = time.time() sofar = now - self._start_time remaining = sofar / self._completed * ( self._remaining + len(self._running)) rstr = 'ETA %.1f sec; %s' % (remaining, rstr) if waiting_for is not None: wstr = ' next: %s @ %.2f cpu' % (waiting_for, waiting_for_cost) else: wstr = '' message( 'WAITING', '%s%d jobs running, %d complete, %d failed (load %.2f)%s' % (rstr, len(self._running), self._completed, self._failures, self.cpu_cost(), wstr)) if platform_string() == 'windows': time.sleep(0.1) else: signal.alarm(10) signal.pause() def cancelled(self): """Poll for cancellation.""" if self._cancelled: return True if not self._check_cancelled(): return False for job in self._running: job.kill() self._cancelled = True return True def finish(self): while self._running: if self.cancelled(): pass # poll cancellation self.reap() if platform_string() != 'windows': signal.alarm(0) return not self.cancelled() and self._failures == 0 def _never_cancelled(): return False def tag_remaining(xs): staging = [] for x in xs: staging.append(x) if len(staging) > 5000: yield (staging.pop(0), None) n = len(staging) for i, x in enumerate(staging): yield (x, n - i - 1) def run(cmdlines, check_cancelled=_never_cancelled, maxjobs=None, maxjobs_cpu_agnostic=None, newline_on_success=False, travis=False, infinite_runs=False, stop_on_failure=False, add_env={}, skip_jobs=False, quiet_success=False, max_time=-1): if skip_jobs: resultset = {} skipped_job_result = JobResult() skipped_job_result.state = 'SKIPPED' for job in cmdlines: message('SKIPPED', job.shortname, do_newline=True) resultset[job.shortname] = [skipped_job_result] return 0, resultset js = Jobset(check_cancelled, maxjobs if maxjobs is not None else _DEFAULT_MAX_JOBS, maxjobs_cpu_agnostic if maxjobs_cpu_agnostic is not None else _DEFAULT_MAX_JOBS, newline_on_success, travis, stop_on_failure, add_env, quiet_success, max_time) for cmdline, remaining in tag_remaining(cmdlines): if not js.start(cmdline): break if remaining is not None: js.set_remaining(remaining) js.finish() return js.get_num_failures(), js.resultset