def getLogger(cls) -> logging.Logger:
"""
Get the logger that logs real-time to the leader.
Note that if the returned logger is used on the leader, you will see the message twice,
since it still goes to the normal log handlers, too.
"""
# Only do the setup once, so we don't add a handler every time we log. Use a lock to do
# so safely even if we're being called in different threads. Use double-checked locking
# to reduce the overhead introduced by the lock.
if cls.logger is None:
with cls.lock:
if cls.logger is None:
cls.logger = logging.getLogger('toil-rt')
try:
level = os.environ[cls.envPrefix + 'LEVEL']
except KeyError:
# There is no server running on the leader, so suppress most log messages
# and skip the UDP stuff.
cls.logger.setLevel(logging.CRITICAL)
else:
# Adopt the logging level set on the leader.
set_log_level(level, cls.logger)
try:
address = os.environ[cls.envPrefix + 'ADDRESS']
except KeyError:
pass
else:
# We know where to send messages to, so send them.
host, port = address.split(':')
cls.logger.addHandler(
JSONDatagramHandler(host, int(port)))
return cls.logger
def workerScript(jobStore,
config,
jobName,
jobStoreID,
redirectOutputToLogFile=True):
"""
Worker process script, runs a job.
:param str jobName: The "job name" (a user friendly name) of the job to be run
:param str jobStoreLocator: Specifies the job store to use
:param str jobStoreID: The job store ID of the job to be run
:return int: 1 if a job failed, or 0 if all jobs succeeded
"""
configure_root_logger()
set_log_level(config.logLevel)
##########################################
#Create the worker killer, if requested
##########################################
logFileByteReportLimit = config.maxLogFileSize
if config.badWorker > 0 and random.random() < config.badWorker:
# We need to kill the process we are currently in, to simulate worker
# failure. We don't want to just send SIGKILL, because we can't tell
# that from a legitimate OOM on our CI runner. We're going to send
# SIGUSR1 so our terminations are distinctive, and then SIGKILL if that
# didn't stick. We definitely don't want to do this from *within* the
# process we are trying to kill, so we fork off. TODO: We can still
# leave the killing code running after the main Toil flow is done, but
# since it's now in a process instead of a thread, the main Python
# process won't wait around for its timeout to expire. I think this is
# better than the old thread-based way where all of Toil would wait
# around to be killed.
killTarget = os.getpid()
sleepTime = config.badWorkerFailInterval * random.random()
if os.fork() == 0:
# We are the child
# Let the parent run some amount of time
time.sleep(sleepTime)
# Kill it gently
os.kill(killTarget, signal.SIGUSR1)
# Wait for that to stick
time.sleep(0.01)
try:
# Kill it harder. Hope the PID hasn't already been reused.
# If we succeeded the first time, this will OSError
os.kill(killTarget, signal.SIGKILL)
except OSError:
pass
# Exit without doing any of Toil's cleanup
os._exit(0)
# We don't need to reap the child. Either it kills us, or we finish
# before it does. Either way, init will have to clean it up for us.
##########################################
#Load the environment for the job
##########################################
#First load the environment for the job.
with jobStore.readSharedFileStream("environment.pickle") as fileHandle:
environment = safeUnpickleFromStream(fileHandle)
env_reject = {
"TMPDIR", "TMP", "HOSTNAME", "HOSTTYPE", "HOME", "LOGNAME", "USER",
"DISPLAY", "JAVA_HOME"
}
for i in environment:
if i == "PATH":
# Handle path specially. Sometimes e.g. leader may not include
# /bin, but the Toil appliance needs it.
if i in os.environ and os.environ[i] != '':
# Use the provided PATH and then the local system's PATH
os.environ[i] = environment[i] + ':' + os.environ[i]
else:
# Use the provided PATH only
os.environ[i] = environment[i]
elif i not in env_reject:
os.environ[i] = environment[i]
# sys.path is used by __import__ to find modules
if "PYTHONPATH" in environment:
for e in environment["PYTHONPATH"].split(':'):
if e != '':
sys.path.append(e)
toilWorkflowDir = Toil.getLocalWorkflowDir(config.workflowID,
config.workDir)
##########################################
#Setup the temporary directories.
##########################################
# Dir to put all this worker's temp files in.
localWorkerTempDir = tempfile.mkdtemp(dir=toilWorkflowDir)
os.chmod(localWorkerTempDir, 0o755)
##########################################
#Setup the logging
##########################################
#This is mildly tricky because we don't just want to
#redirect stdout and stderr for this Python process; we want to redirect it
#for this process and all children. Consequently, we can't just replace
#sys.stdout and sys.stderr; we need to mess with the underlying OS-level
#file descriptors. See <http://stackoverflow.com/a/11632982/402891>
#When we start, standard input is file descriptor 0, standard output is
#file descriptor 1, and standard error is file descriptor 2.
# Do we even want to redirect output? Let the config make us not do it.
redirectOutputToLogFile = redirectOutputToLogFile and not config.disableWorkerOutputCapture
#What file do we want to point FDs 1 and 2 to?
tempWorkerLogPath = os.path.join(localWorkerTempDir, "worker_log.txt")
if redirectOutputToLogFile:
# Announce that we are redirecting logging, and where it will now go.
# This is important if we are trying to manually trace a faulty worker invocation.
logger.info("Redirecting logging to %s", tempWorkerLogPath)
sys.stdout.flush()
sys.stderr.flush()
# Save the original stdout and stderr (by opening new file descriptors
# to the same files)
origStdOut = os.dup(1)
origStdErr = os.dup(2)
# Open the file to send stdout/stderr to.
logFh = os.open(tempWorkerLogPath,
os.O_WRONLY | os.O_CREAT | os.O_APPEND)
# Replace standard output with a descriptor for the log file
os.dup2(logFh, 1)
# Replace standard error with a descriptor for the log file
os.dup2(logFh, 2)
# Since we only opened the file once, all the descriptors duped from
# the original will share offset information, and won't clobber each
# others' writes. See <http://stackoverflow.com/a/5284108/402891>. This
# shouldn't matter, since O_APPEND seeks to the end of the file before
# every write, but maybe there's something odd going on...
# Close the descriptor we used to open the file
os.close(logFh)
debugging = logging.getLogger().isEnabledFor(logging.DEBUG)
##########################################
#Worker log file trapped from here on in
##########################################
jobAttemptFailed = False
statsDict = MagicExpando()
statsDict.jobs = []
statsDict.workers.logsToMaster = []
blockFn = lambda: True
listOfJobs = [jobName]
job = None
try:
#Put a message at the top of the log, just to make sure it's working.
logger.info("---TOIL WORKER OUTPUT LOG---")
sys.stdout.flush()
logProcessContext(config)
##########################################
#Connect to the deferred function system
##########################################
deferredFunctionManager = DeferredFunctionManager(toilWorkflowDir)
##########################################
#Load the JobDescription
##########################################
jobDesc = jobStore.load(jobStoreID)
listOfJobs[0] = str(jobDesc)
logger.debug("Parsed job description")
##########################################
#Cleanup from any earlier invocation of the job
##########################################
if jobDesc.command == None:
logger.debug("Job description has no body to run.")
# Cleanup jobs already finished
predicate = lambda jID: jobStore.exists(jID)
jobDesc.filterSuccessors(predicate)
jobDesc.filterServiceHosts(predicate)
logger.debug(
"Cleaned up any references to completed successor jobs")
# This cleans the old log file which may
# have been left if the job is being retried after a job failure.
oldLogFile = jobDesc.logJobStoreFileID
if oldLogFile != None:
jobDesc.logJobStoreFileID = None
jobStore.update(jobDesc) #Update first, before deleting any files
jobStore.deleteFile(oldLogFile)
##########################################
# If a checkpoint exists, restart from the checkpoint
##########################################
if isinstance(
jobDesc,
CheckpointJobDescription) and jobDesc.checkpoint is not None:
# The job is a checkpoint, and is being restarted after previously completing
logger.debug("Job is a checkpoint")
# If the checkpoint still has extant successors or services, its
# subtree didn't complete properly. We handle the restart of the
# checkpoint here, removing its previous subtree.
if next(jobDesc.successorsAndServiceHosts(), None) is not None:
logger.debug("Checkpoint has failed; restoring")
# Reduce the try count
assert jobDesc.remainingTryCount >= 0
jobDesc.remainingTryCount = max(0,
jobDesc.remainingTryCount - 1)
jobDesc.restartCheckpoint(jobStore)
# Otherwise, the job and successors are done, and we can cleanup stuff we couldn't clean
# because of the job being a checkpoint
else:
logger.debug(
"The checkpoint jobs seems to have completed okay, removing any checkpoint files to delete."
)
#Delete any remnant files
list(
map(
jobStore.deleteFile,
list(
filter(jobStore.fileExists,
jobDesc.checkpointFilesToDelete))))
##########################################
#Setup the stats, if requested
##########################################
if config.stats:
startClock = get_total_cpu_time()
startTime = time.time()
while True:
##########################################
#Run the job body, if there is one
##########################################
logger.info("Working on job %s", jobDesc)
if jobDesc.command is not None:
assert jobDesc.command.startswith("_toil ")
logger.debug("Got a command to run: %s" % jobDesc.command)
# Load the job. It will use the same JobDescription we have been using.
job = Job.loadJob(jobStore, jobDesc)
if isinstance(jobDesc, CheckpointJobDescription):
# If it is a checkpoint job, save the command
jobDesc.checkpoint = jobDesc.command
logger.info("Loaded body %s from description %s", job, jobDesc)
# Create a fileStore object for the job
fileStore = AbstractFileStore.createFileStore(
jobStore,
jobDesc,
localWorkerTempDir,
blockFn,
caching=not config.disableCaching)
with job._executor(stats=statsDict if config.stats else None,
fileStore=fileStore):
with deferredFunctionManager.open() as defer:
with fileStore.open(job):
# Get the next block function to wait on committing this job
blockFn = fileStore.waitForCommit
# Run the job, save new successors, and set up
# locally (but don't commit) successor
# relationships and job completion.
# Pass everything as name=value because Cactus
# likes to override _runner when it shouldn't and
# it needs some hope of finding the arguments it
# wants across multiple Toil versions. We also
# still pass a jobGraph argument to placate old
# versions of Cactus.
job._runner(jobGraph=None,
jobStore=jobStore,
fileStore=fileStore,
defer=defer)
# Accumulate messages from this job & any subsequent chained jobs
statsDict.workers.logsToMaster += fileStore.loggingMessages
logger.info("Completed body for %s", jobDesc)
else:
#The command may be none, in which case
#the JobDescription is either a shell ready to be deleted or has
#been scheduled after a failure to cleanup
logger.debug("No user job to run, so finishing")
break
if AbstractFileStore._terminateEvent.isSet():
raise RuntimeError("The termination flag is set")
##########################################
#Establish if we can run another job within the worker
##########################################
successor = nextChainable(jobDesc, jobStore, config)
if successor is None or config.disableChaining:
# Can't chain any more jobs. We are going to stop.
logger.info("Not chaining from job %s", jobDesc)
# TODO: Somehow the commit happens even if we don't start it here.
break
logger.info("Chaining from %s to %s", jobDesc, successor)
##########################################
# We have a single successor job that is not a checkpoint job. We
# reassign the ID of the current JobDescription to the successor.
# We can then delete the successor JobDescription (under its old
# ID) in the jobStore, as it is wholly incorporated into the
# current one.
##########################################
# Make sure nothing has gone wrong and we can really chain
assert jobDesc.memory >= successor.memory
assert jobDesc.cores >= successor.cores
# Save the successor's original ID, so we can clean it (and its
# body) up after we finish executing it.
successorID = successor.jobStoreID
# add the successor to the list of jobs run
listOfJobs.append(str(successor))
# Now we need to become that successor, under the original ID.
successor.replace(jobDesc)
jobDesc = successor
# Problem: successor's job body is a file that will be cleaned up
# when we delete the successor job by ID. We can't just move it. So
# we need to roll up the deletion of the successor job by ID with
# the deletion of the job ID we're currently working on.
jobDesc.jobsToDelete.append(successorID)
# Clone the now-current JobDescription (which used to be the successor).
# TODO: Why??? Can we not?
jobDesc = copy.deepcopy(jobDesc)
# Build a fileStore to update the job and commit the replacement.
# TODO: can we have a commit operation without an entire FileStore???
fileStore = AbstractFileStore.createFileStore(
jobStore,
jobDesc,
localWorkerTempDir,
blockFn,
caching=not config.disableCaching)
# Update blockFn to wait for that commit operation.
blockFn = fileStore.waitForCommit
# This will update the job once the previous job is done updating
fileStore.startCommit(jobState=True)
# Clone the current job description again, so that further updates
# to it (such as new successors being added when it runs) occur
# after the commit process we just kicked off, and aren't committed
# early or partially.
jobDesc = copy.deepcopy(jobDesc)
logger.debug("Starting the next job")
##########################################
#Finish up the stats
##########################################
if config.stats:
totalCPUTime, totalMemoryUsage = get_total_cpu_time_and_memory_usage(
)
statsDict.workers.time = str(time.time() - startTime)
statsDict.workers.clock = str(totalCPUTime - startClock)
statsDict.workers.memory = str(totalMemoryUsage)
# log the worker log path here so that if the file is truncated the path can still be found
if redirectOutputToLogFile:
logger.info(
"Worker log can be found at %s. Set --cleanWorkDir to retain this log",
localWorkerTempDir)
logger.info(
"Finished running the chain of jobs on this node, we ran for a total of %f seconds",
time.time() - startTime)
##########################################
#Trapping where worker goes wrong
##########################################
except: #Case that something goes wrong in worker
traceback.print_exc()
logger.error("Exiting the worker because of a failed job on host %s",
socket.gethostname())
AbstractFileStore._terminateEvent.set()
##########################################
#Wait for the asynchronous chain of writes/updates to finish
##########################################
blockFn()
##########################################
#All the asynchronous worker/update threads must be finished now,
#so safe to test if they completed okay
##########################################
if AbstractFileStore._terminateEvent.isSet():
# Something has gone wrong.
# Clobber any garbage state we have for this job from failing with
# whatever good state is still stored in the JobStore
jobDesc = jobStore.load(jobStoreID)
# Remember that we failed
jobAttemptFailed = True
##########################################
#Cleanup
##########################################
# Close the worker logging
# Flush at the Python level
sys.stdout.flush()
sys.stderr.flush()
if redirectOutputToLogFile:
# Flush at the OS level
os.fsync(1)
os.fsync(2)
# Close redirected stdout and replace with the original standard output.
os.dup2(origStdOut, 1)
# Close redirected stderr and replace with the original standard error.
os.dup2(origStdErr, 2)
# sys.stdout and sys.stderr don't need to be modified at all. We don't
# need to call redirectLoggerStreamHandlers since they still log to
# sys.stderr
# Close our extra handles to the original standard output and standard
# error streams, so we don't leak file handles.
os.close(origStdOut)
os.close(origStdErr)
# Now our file handles are in exactly the state they were in before.
# Copy back the log file to the global dir, if needed.
# Note that we work with bytes instead of characters so we can seek
# relative to the end (since Python won't decode Unicode backward, or even
# interpret seek offsets in characters for us). TODO: We may get invalid or
# just different Unicode by breaking up a character at the boundary!
if jobAttemptFailed and redirectOutputToLogFile:
jobDesc.logJobStoreFileID = jobStore.getEmptyFileStoreID(
jobDesc.jobStoreID, cleanup=True)
jobDesc.chainedJobs = listOfJobs
with jobStore.updateFileStream(jobDesc.logJobStoreFileID) as w:
with open(tempWorkerLogPath, 'rb') as f:
if os.path.getsize(
tempWorkerLogPath) > logFileByteReportLimit != 0:
if logFileByteReportLimit > 0:
f.seek(-logFileByteReportLimit,
2) # seek to last tooBig bytes of file
elif logFileByteReportLimit < 0:
f.seek(logFileByteReportLimit,
0) # seek to first tooBig bytes of file
# Dump the possibly-invalid-Unicode bytes into the log file
w.write(f.read()) # TODO load file using a buffer
# Commit log file reference back to JobStore
jobStore.update(jobDesc)
elif ((debugging or (config.writeLogsFromAllJobs
and not jobName.startswith(CWL_INTERNAL_JOBS)))
and redirectOutputToLogFile): # write log messages
with open(tempWorkerLogPath, 'rb') as logFile:
if os.path.getsize(
tempWorkerLogPath) > logFileByteReportLimit != 0:
if logFileByteReportLimit > 0:
logFile.seek(-logFileByteReportLimit,
2) # seek to last tooBig bytes of file
elif logFileByteReportLimit < 0:
logFile.seek(logFileByteReportLimit,
0) # seek to first tooBig bytes of file
# Make sure lines are Unicode so they can be JSON serialized as part of the dict.
# We may have damaged the Unicode text by cutting it at an arbitrary byte so we drop bad characters.
logMessages = [
line.decode('utf-8', 'skip')
for line in logFile.read().splitlines()
]
statsDict.logs.names = listOfJobs
statsDict.logs.messages = logMessages
if (debugging or config.stats or statsDict.workers.logsToMaster
) and not jobAttemptFailed: # We have stats/logging to report back
jobStore.writeStatsAndLogging(
json.dumps(statsDict, ensure_ascii=True).encode())
#Remove the temp dir
cleanUp = config.cleanWorkDir
if cleanUp == 'always' or (cleanUp == 'onSuccess' and
not jobAttemptFailed) or (cleanUp == 'onError'
and jobAttemptFailed):
shutil.rmtree(localWorkerTempDir)
#This must happen after the log file is done with, else there is no place to put the log
if (not jobAttemptFailed) and jobDesc.command == None and next(
jobDesc.successorsAndServiceHosts(), None) is None:
# We can now safely get rid of the JobDescription, and all jobs it chained up
for otherID in jobDesc.jobsToDelete:
jobStore.delete(otherID)
jobStore.delete(jobDesc.jobStoreID)
if jobAttemptFailed:
return 1
else:
return 0
def main():
configure_root_logger()
set_log_level("INFO")
if not os.environ.get("MESOS_AGENT_ENDPOINT"):
# Some Mesos setups in our tests somehow lack this variable. Provide a
# fake one to maybe convince the executor driver to work.
os.environ["MESOS_AGENT_ENDPOINT"] = os.environ.get(
"MESOS_SLAVE_ENDPOINT", "127.0.0.1:5051")
log.warning("Had to fake MESOS_AGENT_ENDPOINT as %s" %
os.environ["MESOS_AGENT_ENDPOINT"])
# must be set manually to enable toggling of the mesos log level for debugging jenkins
# may be useful: https://github.com/DataBiosphere/toil/pull/2338#discussion_r223854931
if False:
try:
urlopen("http://%s/logging/toggle?level=1&duration=15mins" %
os.environ["MESOS_AGENT_ENDPOINT"]).read()
log.debug("Toggled agent log level")
except Exception:
log.debug("Failed to toggle agent log level")
# Parse the agent state
agent_state = json.loads(
urlopen("http://%s/state" % os.environ["MESOS_AGENT_ENDPOINT"]).read())
if 'completed_frameworks' in agent_state:
# Drop the completed frameworks which grow over time
del agent_state['completed_frameworks']
log.debug("Agent state: %s", str(agent_state))
log.debug("Virtual memory info in executor: %s" %
repr(psutil.virtual_memory()))
if os.path.exists('/sys/fs/cgroup/memory'):
# Mesos can limit memory with a cgroup, so we should report on that.
for (dirpath, dirnames, filenames) in os.walk('/sys/fs/cgroup/memory',
followlinks=True):
for filename in filenames:
if 'limit_in_bytes' not in filename:
continue
log.debug('cgroup memory info from %s:' %
os.path.join(dirpath, filename))
try:
for line in open(os.path.join(dirpath, filename)):
log.debug(line.rstrip())
except Exception:
log.debug("Failed to read file")
# Mesos can also impose rlimit limits, including on things that really
# ought to not be limited, like virtual address space size.
log.debug('DATA rlimit: %s', str(resource.getrlimit(resource.RLIMIT_DATA)))
log.debug('STACK rlimit: %s',
str(resource.getrlimit(resource.RLIMIT_STACK)))
log.debug('RSS rlimit: %s', str(resource.getrlimit(resource.RLIMIT_RSS)))
log.debug('AS rlimit: %s', str(resource.getrlimit(resource.RLIMIT_AS)))
executor = MesosExecutor()
log.debug('Made executor')
driver = MesosExecutorDriver(executor, use_addict=True)
old_on_event = driver.on_event
def patched_on_event(event):
"""
Intercept and log all pymesos events.
"""
log.debug("Event: %s", repr(event))
old_on_event(event)
driver.on_event = patched_on_event
log.debug('Made driver')
driver.start()
log.debug('Started driver')
driver_result = driver.join()
log.debug('Joined driver')
# Tolerate a None in addition to the code the docs suggest we should receive from join()
exit_value = 0 if (driver_result is None
or driver_result == 'DRIVER_STOPPED') else 1
assert len(executor.runningTasks) == 0
sys.exit(exit_value)
def executor() -> None:
"""
Main function of the _toil_contained_executor entrypoint.
Runs inside the Toil container.
Responsible for setting up the user script and running the command for the
job (which may in turn invoke the Toil worker entrypoint).
"""
configure_root_logger()
set_log_level("DEBUG")
logger.debug("Starting executor")
# If we don't manage to run the child, what should our exit code be?
exit_code = EXIT_STATUS_UNAVAILABLE_VALUE
if len(sys.argv) != 2:
logger.error('Executor requires exactly one base64-encoded argument')
sys.exit(exit_code)
# Take in a base64-encoded pickled dict as our first argument and decode it
try:
# Make sure to encode the text arguments to bytes before base 64 decoding
job = pickle.loads(base64.b64decode(sys.argv[1].encode('utf-8')))
except:
exc_info = sys.exc_info()
logger.error('Exception while unpickling task: ', exc_info=exc_info)
sys.exit(exit_code)
if 'environment' in job:
# Adopt the job environment into the executor.
# This lets us use things like TOIL_WORKDIR when figuring out how to talk to other executors.
logger.debug('Adopting environment: %s', str(job['environment'].keys()))
for var, value in job['environment'].items():
os.environ[var] = value
# Set JTRES_ROOT and other global state needed for resource
# downloading/deployment to work.
# TODO: Every worker downloads resources independently.
# We should have a way to share a resource directory.
logger.debug('Preparing system for resource download')
Resource.prepareSystem()
try:
if 'userScript' in job:
job['userScript'].register()
# Start the child process
logger.debug("Invoking command: '%s'", job['command'])
child = subprocess.Popen(job['command'],
preexec_fn=lambda: os.setpgrp(),
shell=True)
# Reproduce child's exit code
exit_code = child.wait()
except:
# This will print a traceback for us, since exit() in the finally
# will bypass the normal way of getting one.
logger.exception('Encountered exception running child')
finally:
logger.debug('Cleaning up resources')
# TODO: Change resource system to use a shared resource directory for everyone.
# Then move this into worker cleanup somehow
Resource.cleanSystem()
logger.debug('Shutting down')
sys.exit(exit_code)