def monitorRender(self, timeout=1800):
logging.debug("Monitoring Render...")
mainIdleTime = time.time()
frameIdleTime = time.time()
while True:
where = self.readLogFile.tell()
line = self.readLogFile.readline()
if not line:
time.sleep(.3)
self.readLogFile.seek(where)
if time.time() - mainIdleTime > timeout:
raise RuntimeError("Frame timeout reached.")
else:
'''
Reset the idle time each time a new line is read.
If the frame timeout is reached, raise an exception.
'''
mainIdleTime = time.time()
''' Retrieve the info from each line of output '''
self.currFrame = self.reSearch(self.progressPattern, line)
if self.currFrame != "":
self.currFrame = str(
int(self.startFrame) + int(self.currFrame) - 1)
# logging.debug("Last Completed Frame: " + currFrame)
if not self.isOutputMovie:
self.verifyCurrFrame()
if not self.alreadyComplete:
if time.time(
) - frameIdleTime > self.chunkProgressDelay:
logging.debug("Chunk Progress: " +
str(self.getChunkProgress()))
resultPackage = {
'progress': str(self.getChunkProgress())
}
self.agendaItem['resultpackage'] = resultPackage
qb.reportwork(self.agendaItem)
frameIdleTime = time.time()
complete = self.reSearch(self.completePattern, line)
if complete:
break
closed = self.reSearch(self.closedPattern, line)
if closed:
break
self.deleteCorruptFrames()
if self.corruptFrames:
return False
else:
return True
def run(self):
print "start"
self.logFile.write("start\n")
# Grab the first agenda item
print "Requesting Work:"
self.logFile.write("Requesting Work\n")
self.currAgendaItem = qb.requestwork()
print "Got Work"
self.logFile.write("Got Work\n")
self.logFile.write("Work: " + str(self.currAgendaItem) + '\n')
print "Work: " + str(self.currAgendaItem)
while True:
# Get the progress from the queue
progress = int(self.queue.get())
# Loop to update progress gaps
while True:
agendaProgress = int(
self.currAgendaItem['id']
) # ID represents the percent complete 1-100
if (progress >= agendaProgress):
self.currAgendaItem['status'] = 'complete'
qb.reportwork(self.currAgendaItem)
# Get a new agenda item if possible
self.currAgendaItem = qb.requestwork()
self.logFile.write("Work: " + str(self.currAgendaItem) +
'\n')
print "Work: " + str(self.currAgendaItem)
if (int(self.currAgendaItem['id']) == -1
or int(self.currAgendaItem['id']) == 101):
break
elif (progress < agendaProgress):
break
# Signal that the queue task is complete
self.queue.task_done()
# If the job is complete, empty the queue of remaining jobs
if (int(self.currAgendaItem['id']) == -1
or int(self.currAgendaItem['id']) == 101):
print 'Reporter: Job Complete, emptying queue of ' + str(
self.queue.qsize()) + ' extra jobs'
while True:
self.queue.get()
self.queue.task_done()
self.logFile.close()
def monitorRender(self, timeout=1800):
logging.debug("Monitoring Render...")
mainIdleTime = time.time()
frameIdleTime = time.time()
while True:
where = self.readLogFile.tell()
line = self.readLogFile.readline()
if not line:
time.sleep(.3)
self.readLogFile.seek(where)
if time.time() - mainIdleTime > timeout:
raise RuntimeError("Frame timeout reached.")
else:
'''
Reset the idle time each time a new line is read.
If the frame timeout is reached, raise an exception.
'''
mainIdleTime = time.time()
''' Retrieve the info from each line of output '''
self.currFrame = self.reSearch(self.progressPattern, line)
if self.currFrame != "":
self.currFrame = str(int(self.startFrame) + int(self.currFrame) - 1)
# logging.debug("Last Completed Frame: " + currFrame)
if not self.isOutputMovie:
self.verifyCurrFrame()
if not self.alreadyComplete:
if time.time() - frameIdleTime > self.chunkProgressDelay:
logging.debug("Chunk Progress: " + str(self.getChunkProgress()))
resultPackage = {'progress':str(self.getChunkProgress())}
self.agendaItem['resultpackage'] = resultPackage
qb.reportwork(self.agendaItem)
frameIdleTime = time.time()
complete = self.reSearch(self.completePattern, line)
if complete:
break
closed = self.reSearch(self.closedPattern, line)
if closed:
break
self.deleteCorruptFrames()
if self.corruptFrames:
return False
else:
return True
def run(self):
print "start"
self.logFile.write("start\n")
# Grab the first agenda item
print "Requesting Work:"
self.logFile.write("Requesting Work\n")
self.currAgendaItem = qb.requestwork()
print "Got Work"
self.logFile.write("Got Work\n")
self.logFile.write("Work: " + str(self.currAgendaItem) + '\n')
print "Work: " + str(self.currAgendaItem)
while True:
# Get the progress from the queue
progress = int(self.queue.get())
# Loop to update progress gaps
while True:
agendaProgress = int(self.currAgendaItem['id']) # ID represents the percent complete 1-100
if (progress >= agendaProgress):
self.currAgendaItem['status'] = 'complete'
qb.reportwork(self.currAgendaItem)
# Get a new agenda item if possible
self.currAgendaItem = qb.requestwork()
self.logFile.write("Work: " + str(self.currAgendaItem) + '\n')
print "Work: " + str(self.currAgendaItem)
if (int(self.currAgendaItem['id']) == -1 or int(self.currAgendaItem['id']) == 101):
break
elif (progress < agendaProgress):
break
# Signal that the queue task is complete
self.queue.task_done()
# If the job is complete, empty the queue of remaining jobs
if (int(self.currAgendaItem['id']) == -1 or int(self.currAgendaItem['id']) == 101):
print 'Reporter: Job Complete, emptying queue of ' + str(self.queue.qsize()) + ' extra jobs'
while True:
self.queue.get()
self.queue.task_done()
self.logFile.close()
def main():
"""The main worker, responsible for all direct communication with Qube.
Since this is the only process that is able to communicate directly with
Qube, we do not have control over what specific process is called, and we
will often want to run code in a different interpreter, this function does
not execute the job directly. Instead, is spawns a child which it talks to
via pipes. This also gives us the oppourtunity to bootstrap the development
environment if needed.
"""
log('using worker %s' % __file__)
job = qb.jobobj()
log('recieved job %d' % job['id'])
# We don't need the child to have the full agenda.
job_for_child = dict(job)
job_for_child.pop('agenda', None)
# The main loop. Continuously request more work and dispatch it to a child.
# Keep on going until we are no longer given an agenda that we can operate
# on.
while True:
agenda = qb.requestwork()
log('recieved work %r (%s)' % (agenda['name'], agenda['status']))
sys.stdout.flush()
# Be aware that we cannot unpack the agenda at this point since it may
# reply upon the child's environment in order to function.
# Handle finished states. When a job is complete Qube will continue to
# hand us agendas, but they will have a status that indicates that we
# cannot work on them. So we report that as the final job status and
# finish working on it.
if agenda['status'] in ('complete', 'pending', 'blocked'):
# 'complete' -> No more frames.
# 'pending' -> Preempted, so bail out.
# 'blocked' -> Perhaps item is part of a dependency.
log('reporting job as %s' % agenda['status'])
qb.reportjob(agenda['status'])
log('worker shutting down')
return
# Waiting; relatively rare, try again shortly.
elif agenda['status'] == 'waiting':
timeout = 10 # seconds
log('job %s is waiting for %ds' % (job['id'], timeout))
time.sleep(timeout)
continue
package_to_print = dict(agenda['package'])
package_to_print.pop('__pickle__', None)
log('work package')
pprint.pprint(package_to_print)
print '# ---'
# Prepare some pipes for communicating with the subprocess.
request_pipe = os.pipe()
response_pipe = os.pipe()
# Open the process, doing a dev bootstrap if this is a dev environment.
# We are calling this module, which will end up calling the
# :func:`execute` function.
cmd = []
if 'VEE_EXEC_ARGS' in os.environ or 'KS_DEV_ARGS' in os.environ:
# These both have a "dev" command with a "--bootstrap" which do
# the same thing.
cmd.extend(('dev', '--bootstrap'))
cmd.extend((
agenda['package'].get('interpreter', 'python'),
'-m',
'qbfutures.sandbox.the_corner',
str(request_pipe[0]),
str(response_pipe[1]),
))
log('spawning child: %s' % subprocess.list2cmdline(cmd))
proc = subprocess.Popen(cmd, close_fds=False)
# Close our end of the pipes so that there is only one process which
# still has them open (the child).
os.close(request_pipe[0])
os.close(response_pipe[1])
# Send the job and agenda package to the child.
with os.fdopen(request_pipe[1], 'w') as request_fh:
pickle.dump(job_for_child, request_fh, -1)
pickle.dump(agenda['package'], request_fh, -1)
# Get the response from the child.
with os.fdopen(response_pipe[0], 'r') as response_fh:
try:
package = pickle.load(response_fh)
except Exception as e:
traceback.print_exc()
sys.stderr.flush()
package = {
'status': 'failed',
'exception': e,
}
# Wait for the child to finish.
# log('waiting for child...')
proc.wait()
package.setdefault('status', 'failed')
agenda['resultpackage'] = utils.pack(package)
agenda['status'] = package['status']
log('work resultpackage')
pprint.pprint(package)
print '# ---'
if agenda['status'] == 'failed':
log('os.environ')
for k, v in sorted(os.environ.iteritems()):
print '# %s = %r' % (k, v)
print '# ---'
log('reporting work as %s' % agenda['status'])
qb.reportwork(agenda)
def executeJob(job):
'''
Execute the transcoding process.
'''
# Convert the paths
logging.debug("#### Start Path Convert")
job = pathConvert.convertDict(job)
logging.debug("#### End Path Convert")
jobstate = 'pending'
pkg = job.setdefault('package', {})
# logger.debug("Qube Job: " + str(job))
try:
memUsage = setupAEMemory()
if memUsage['error'] == True:
raise Exception, "Fatal Error with Memory Usage"
# Setup multiprocessing
multProcs = memUsage['multProcs']
ramPerCPU = 2
if (pkg.has_key("complexity")):
logging.debug("complexity found")
complexValue = pkg["complexity"].lower()
if complexValue == "normal":
pass
elif complexValue == "complex":
multProcs = True
ramPerCPU = 3
elif complexValue == "simple":
multProcs = False
# Get the number of virtual cores
cores = getCPUCores(memUsage['aeAvailMem'] / 1024, ramPerCPU)
logging.debug("Cores: %s" % cores)
script = "RenderTools.setMultiprocessing(\"%s\",%d, %d);" % (
multProcs, ramPerCPU, cores['reserved'])
if (multProcs):
logging.info(
"Multiprocessing: %s - %dGB per CPU with %d Cores Available" %
(multProcs, ramPerCPU, cores['available']))
else:
logging.info("Multiprocessing: %s" % multProcs)
aeSocket = AESocket.AESocket()
aeSocket.launchAERender(multProcs,
projectFile=pkg['renderProjectPath'])
# Load the render tools
script = "$.evalFile(new File(\"%s\"));\"Render Tools Loaded\"" % os.path.abspath(
RENDERTOOLS)
logging.debug("Render Tools Script: %s" % script)
aeSocket.runScript(script, "Render Tools Setup")
script = "RenderTools.openProject(\"%s\");" % pkg['renderProjectPath']
result = aeSocket.runScript(script, "Open Project")
logging.debug("Open Project Result: %s" % script)
# Finalize multiprocessing setting
# result = aeSocket.runScript(script, "Set Multiprocessing")
# logging.debug("Set Multiprocessing Result: %s" % result)
# script = "RenderTools.setRenderQuality(\"%s\");" % pkg['quality']
# result = aeSocket.runScript(script, "Set Render Quality")
# logging.debug("Set Render Quality Result: %s" % script)
while 1:
agendaItem = qb.requestwork()
logger.debug("Agenda Item: " + str(agendaItem))
returnCode = 0
'''
First Handle non-running state cases
'''
if agendaItem['status'] in ('complete', 'pending', 'blocked',
'waiting'):
'''
complete -- no more frames
pending -- preempted, so bail out
blocked -- perhaps item is part of a dependency
'''
jobstate = agendaItem['status']
logger.debug('Job %s state is now %s' % (job['id'], jobstate))
break
'''
Main
'''
if agendaItem['name'].strip() != '':
if '-' in agendaItem['name']:
startFrame, endFrame = agendaItem['name'].split('-')
else:
startFrame = endFrame = agendaItem['name']
logger.debug("startFrame: " + str(startFrame) + " endFrame: " +
str(endFrame))
script = "RenderTools.setupSegment(%s, %s, %s);" % (
startFrame, endFrame, pkg['rqIndex'])
logging.debug("Setup Segment Script: %s" % script)
aeSocket.runScript(script, "Setup Segment")
outputs = pkg['outputFiles'].split(",")
logger.debug("Outputs: " + str(outputs))
renderTools = Tools.Tools(agendaItem, outputs,
aeSocket.logFilePath, startFrame,
endFrame)
script = "RenderTools.renderQueued();"
aeSocket._sendScript(script, "Render Queued",
timeout=None) # Disable timeout here
monitorResult = renderTools.monitorRender(
timeout=1800) # Max time for frame is 30min
socketResult = aeSocket.getResponse()
renderTools.alreadyComplete = True
if socketResult == True:
returnCode = 1
if not monitorResult:
returnCode = 2
outputPaths = renderTools.getOutputPaths(startFrame, endFrame)
for path in outputPaths:
if not os.path.exists(path):
logging.error("Frame doesn't exist: %s" % path)
returnCode = 3
'''
Update the work status based on the return code.
'''
if returnCode == 0:
outputPaths = pathConvert.convertList(outputPaths,
reverse=True)
agendaItem['resultpackage'] = {
'outputPaths': ','.join(outputPaths),
'progress': '1'
}
agendaItem['status'] = 'complete'
else:
agendaItem['status'] = 'failed'
''' Report back the results to the Supervisor '''
qb.reportwork(agendaItem)
except Exception, e:
exc_type, exc_value, exc_traceback = sys.exc_info()
logger.error(repr(traceback.extract_tb(exc_traceback)))
logger.error(
repr(traceback.format_exception(exc_type, exc_value,
exc_traceback)))
def executeJob(job):
'''
Execute the transcoding process.
'''
# Convert the paths
logging.debug("#### Start Path Convert")
job = pathConvert.convertDict(job)
logging.debug("#### End Path Convert")
jobstate = 'pending'
pkg = job.setdefault('package', {})
# logger.debug("Qube Job: " + str(job))
try:
memUsage = setupAEMemory()
if memUsage['error'] == True:
raise Exception, "Fatal Error with Memory Usage"
# Setup multiprocessing
multProcs = memUsage['multProcs']
ramPerCPU = 2
if (pkg.has_key("complexity")):
logging.debug("complexity found")
complexValue = pkg["complexity"].lower()
if complexValue == "normal":
pass
elif complexValue == "complex":
multProcs = True
ramPerCPU = 3
elif complexValue == "simple":
multProcs = False
# Get the number of virtual cores
cores = getCPUCores(memUsage['aeAvailMem']/1024, ramPerCPU)
logging.debug("Cores: %s" % cores)
script = "RenderTools.setMultiprocessing(\"%s\",%d, %d);" % (multProcs, ramPerCPU, cores['reserved'])
if (multProcs):
logging.info("Multiprocessing: %s - %dGB per CPU with %d Cores Available" % (multProcs, ramPerCPU, cores['available']))
else:
logging.info("Multiprocessing: %s" % multProcs)
aeSocket = AESocket.AESocket()
aeSocket.launchAERender(multProcs, projectFile=pkg['renderProjectPath'])
# Load the render tools
script = "$.evalFile(new File(\"%s\"));\"Render Tools Loaded\"" % os.path.abspath(RENDERTOOLS)
logging.debug("Render Tools Script: %s" % script)
aeSocket.runScript(script, "Render Tools Setup")
script = "RenderTools.openProject(\"%s\");" % pkg['renderProjectPath']
result = aeSocket.runScript(script, "Open Project")
logging.debug("Open Project Result: %s" % script)
# Finalize multiprocessing setting
# result = aeSocket.runScript(script, "Set Multiprocessing")
# logging.debug("Set Multiprocessing Result: %s" % result)
# script = "RenderTools.setRenderQuality(\"%s\");" % pkg['quality']
# result = aeSocket.runScript(script, "Set Render Quality")
# logging.debug("Set Render Quality Result: %s" % script)
while 1:
agendaItem = qb.requestwork()
logger.debug("Agenda Item: " + str(agendaItem))
returnCode = 0
'''
First Handle non-running state cases
'''
if agendaItem['status'] in ('complete', 'pending', 'blocked', 'waiting'):
'''
complete -- no more frames
pending -- preempted, so bail out
blocked -- perhaps item is part of a dependency
'''
jobstate = agendaItem['status']
logger.debug('Job %s state is now %s' % (job['id'], jobstate))
break
'''
Main
'''
if agendaItem['name'].strip() != '':
if '-' in agendaItem['name']:
startFrame, endFrame = agendaItem['name'].split('-')
else:
startFrame = endFrame = agendaItem['name']
logger.debug("startFrame: " + str(startFrame) + " endFrame: " + str(endFrame))
script = "RenderTools.setupSegment(%s, %s, %s);" % (startFrame, endFrame, pkg['rqIndex'])
logging.debug("Setup Segment Script: %s" % script)
aeSocket.runScript(script, "Setup Segment")
outputs = pkg['outputFiles'].split(",")
logger.debug("Outputs: " + str(outputs))
renderTools = Tools.Tools(agendaItem, outputs, aeSocket.logFilePath, startFrame, endFrame)
script = "RenderTools.renderQueued();"
aeSocket._sendScript(script, "Render Queued", timeout=None) # Disable timeout here
monitorResult = renderTools.monitorRender(timeout=1800) # Max time for frame is 30min
socketResult = aeSocket.getResponse()
renderTools.alreadyComplete = True
if socketResult == True:
returnCode = 1
if not monitorResult:
returnCode = 2
outputPaths = renderTools.getOutputPaths(startFrame, endFrame)
for path in outputPaths:
if not os.path.exists(path):
logging.error("Frame doesn't exist: %s" % path)
returnCode = 3
'''
Update the work status based on the return code.
'''
if returnCode == 0:
outputPaths = pathConvert.convertList(outputPaths, reverse=True)
agendaItem['resultpackage'] = {'outputPaths': ','.join(outputPaths),'progress':'1'}
agendaItem['status'] = 'complete'
else:
agendaItem['status'] = 'failed'
''' Report back the results to the Supervisor '''
qb.reportwork(agendaItem)
except Exception, e:
exc_type, exc_value, exc_traceback = sys.exc_info()
logger.error(repr(traceback.extract_tb(exc_traceback)))
logger.error(repr(traceback.format_exception(exc_type, exc_value, exc_traceback)))
def executeJob(control):
'''
Execute the transcoding process.
'''
jobstate = 'pending'
qbJob = control.getQubeJobObject()
if not control.checkForErrors():
while 1:
agendaItem = qb.requestwork()
returnCode = 1
'''
First Handle non-running state cases
'''
if agendaItem['status'] in ('complete', 'pending', 'blocked',
'waiting'):
'''
complete -- no more frames
pending -- preempted, so bail out
blocked -- perhaps item is part of a dependency
'''
jobstate = agendaItem['status']
logger.info('Job %s state is now %s' % (qbJob['id'], jobstate))
break
'''
Run the transcoding process that corresponds to the agendaItem name.
Initialize
Setup the blender scene.
Segment
Transcode a segment of frames.
Final Output
Merge that output's segments together with audio.
'''
if agendaItem['name'] == 'Initialize':
logger.info('Initializing...\n')
if os.path.exists(control.getBlendFile()):
logger.info("Initialization script alread exists.")
returnCode = 0
else:
returnCode = runCMD(control.getInitCMD(agendaItem))
if returnCode == 0:
logger.info('Initialization Complete! (' +
str(returnCode) + ')\n')
else:
logger.error('Initialization Failed! (' + str(returnCode) +
')\n')
elif agendaItem['name'].startswith('Segment'):
'''
Segment Process:
> Make sure the blender project was created
> Load the segment frame range from the work package.
> Check for missing frames in the segments frame range.
True
> Report an error and end the subjob
False
> Continue with transcode
> Check if smartUpdate is turned on.
True
> Check if the Modification Times Database and the output file exists.
True
> Check if there have been modifications to any frames in this segment.
True
> Continue with transcode
False
> Skip transcoding
> Check if we are still transcoding.
True
> Try to Remove output file if it already exists
Success
> Transcode
Failure
> Add '_' to the output file name and try again until sucess.
Max retry is 3 times, then fail the subjob.
> Check if smartUpdate is turned on.
True
> Update the modification times database
False
> Continue
> Update the resultPackage with whether changes were made and the segment output file.
'''
logger.info("Starting Transcoder Segment Process...")
render = False
error = False
''' Check for the blender project '''
if not os.path.exists(control.getBlendFile()):
logger.error('Blender Project doesn\'t exist.')
error = True
else:
''' Load the frame range from the work package '''
frameRangeString = agendaItem['package']['frameRange']
logging.debug("FrameRangeString: %s" % frameRangeString)
frameRange = sequenceTools.loadFrameRange(frameRangeString)
logging.debug("Loaded frameRange: %s" % frameRange)
''' Check for Missing Frames '''
mySequence = control.getSequence()
missingFrames = mySequence.getMissingFrames(frameRange)
if len(missingFrames) > 0:
logger.error('Missing frames!\n' +
','.join(missingFrames))
error = True
else:
logger.info('No Missing Frames')
if not error:
''' Variables used multiple times '''
segmentFilePath = agendaItem.setdefault('package', {}).get(
'segmentFile', '')
segmentFileExists = os.path.exists(segmentFilePath)
currentModTimes = {}
modTimeDBFile = control.getModTimeDBFile()
if control.getSmartUpdate():
modTimeDBFileExists = os.path.exists(modTimeDBFile)
logger.debug('Segment Output: ' + str(segmentFilePath))
logger.debug('Segment Exists: ' +
str(segmentFileExists))
logger.debug('ModTimeDBFile: ' + str(modTimeDBFile))
logger.debug('ModTimeDBFile Exists: ' +
str(modTimeDBFileExists))
if segmentFileExists and modTimeDBFileExists:
logger.info('Smart Updating')
logger.debug(
'Loading current modification times...')
currentModTimes = mySequence.getModTimes(
frameRange)
logger.debug(
'Current modication times loaded. %s' %
currentModTimes)
logger.debug(
'Comparing modification times for frame range %s...'
% frameRange)
compare = mySequence.compare(
modTimeDBFile,
frameRange,
currentModTimes=currentModTimes)
logger.debug('Sequence Differences: %s' %
str(compare))
differences = ''
if len(compare['Added']) > 0:
frameNumbers = mySequence.getFramesFromFilenames(
compare['Added'])
differences += '\n\tAdded: %s' % mySequence.convertListToRanges(
frameNumbers)
if len(compare['Deleted']) > 0:
frameNumbers = mySequence.getFramesFromFilenames(
compare['Deleted'])
differences += '\n\tDeleted: %s' % mySequence.convertListToRanges(
frameNumbers)
if len(compare['Modified']) > 0:
frameNumbers = mySequence.getFramesFromFilenames(
compare['Modified'])
differences += '\n\tModified: %s' % mySequence.convertListToRanges(
frameNumbers)
if differences:
logger.info('Sequence Differences: %s' %
differences)
render = True
else:
render = True
else:
render = True
if render:
segmentFilePath = control.getValidOutputPath(
segmentFilePath)
if segmentFilePath:
render = True
else:
error = True
if render:
logger.info('Transcoding Segment %s' %
agendaItem['name'])
cmd = control.getSegmentCMD(agendaItem)
returnCode = runCMD(cmd)
logger.info('Transcoding Segment Complete! (' +
str(returnCode) + ')')
if control.getSmartUpdate():
logger.debug("Saved ModTimes: " +
str(currentModTimes))
control.job.sequence.saveModTimes(
modTimeDBFile,
modTimeDict=currentModTimes,
frameRange=frameRange)
logger.info("Saved Modification Times")
else:
if not error:
logger.info("No changes to segment " +
agendaItem['name'])
returnCode = 0
'''
Check if this is the last agenda item that's complete.
If so, unblock the final output subjobs.
'''
agendaItem['resultpackage'] = {
'Changed': render,
'segmentFile': segmentFilePath
}
logger.info("Transcoder Segment Process Complete!\n")
elif agendaItem['name'].startswith('Output'):
'''
Final Output Process
> Gather the output paths and changes for all of the segments
stored in their resultPackages.
> Check if there were changes.
True
> Continue Transcoding
False
> Skip Trancoding
> Load segmentOutputPaths from the agenda
> Check if segmentPaths exist.
True
> Continue Transcoding
False
> Skip Transcoding with error
> Check if output path is valid
True
> Continue Transcoding
False
> Skip Transcoding with error
> Check if we are still transcoding.
True
> Concatenate segments together.
False
> Skip
> Update the resultPackage with the outputPath.
'''
logger.info("Starting Final Output Process...\n")
transcode = False
errors = False
dependantNames = agendaItem.get('package',
{}).get('segmentSubjobs', '')
logger.debug('Dependants Names: ' + str(dependantNames))
dependantSegments = control.getSegments(dependantNames)
logger.debug('Dependants Segments: ' + str(dependantSegments))
finalOutputPath = agendaItem['package']['outputFile']
if finalOutputPath:
transcode = True
else:
errors = True
if transcode:
changes = control.checkSegmentsForChanges(
dependantSegments)
if not changes:
logger.info("No changes to segments.")
if os.path.exists(str(finalOutputPath)):
logger.info('Final output movie already exists. ' +
str(finalOutputPath))
returnCode = 0
transcode = False
else:
logger.info('Final output movie doesn\'t exist. ' +
str(finalOutputPath))
transcode = True
else:
transcode = True
if transcode:
segmentOutputPaths = control.getSegmentOutputPaths(
dependantSegments)
if segmentOutputPaths:
transcode = True
else:
errors = True
if transcode:
startFrame = control.getOutputStartFrame(dependantSegments)
logger.debug('Output Start Frame: ' + startFrame)
if transcode:
finalOutputPath = control.getValidOutputPath(
finalOutputPath)
if finalOutputPath:
transcode = True
else:
errors = True
if transcode:
cmd = control.getFinalOutputCMD(segmentOutputPaths,
finalOutputPath,
startFrame, 29.97,
agendaItem)
returnCode = runCMD(cmd)
if returnCode != 0:
errors = True
else:
logger.info('No changes to Final ' + agendaItem['name'])
if not errors:
agendaItem['resultpackage'] = {
'outputPaths': finalOutputPath
}
logger.info('Transcoder Final ' + agendaItem['name'] +
' Completed Succesfully! (' + str(returnCode) +
')\n')
else:
logger.info('Transcoder Final ' + agendaItem['name'] +
' Failed!' + str(returnCode) + ')\n')
else:
logger.error("Invalid Agenda Item")
logger.error(str(agendaItem))
'''
Update the work status based on the return code.
'''
if returnCode == 0:
agendaItem['status'] = 'complete'
else:
agendaItem['status'] = 'failed'
''' Report back the results to the Supervisor '''
qb.reportwork(agendaItem)
if jobstate == 'blocked':
jobstate = 'pending'
return jobstate
def main():
"""The main worker, responsible for all direct communication with Qube.
Since this is the only process that is able to communicate directly with
Qube, we do not have control over what specific process is called, and we
will often want to run code in a different interpreter, this function does
not execute the job directly. Instead, is spawns a child which it talks to
via pipes. This also gives us the oppourtunity to bootstrap the development
environment if needed.
"""
log('using worker %s' % __file__)
job = qb.jobobj()
log('recieved job %d' % job['id'])
# We don't need the child to have the full agenda.
job_for_child = dict(job)
job_for_child.pop('agenda', None)
# The main loop. Continuously request more work and dispatch it to a child.
# Keep on going until we are no longer given an agenda that we can operate
# on.
while True:
agenda = qb.requestwork()
log('recieved work %r (%s)' % (agenda['name'], agenda['status']))
sys.stdout.flush()
# Be aware that we cannot unpack the agenda at this point since it may
# reply upon the child's environment in order to function.
# Handle finished states. When a job is complete Qube will continue to
# hand us agendas, but they will have a status that indicates that we
# cannot work on them. So we report that as the final job status and
# finish working on it.
if agenda['status'] in ('complete', 'pending', 'blocked'):
# 'complete' -> No more frames.
# 'pending' -> Preempted, so bail out.
# 'blocked' -> Perhaps item is part of a dependency.
log('reporting job as %s' % agenda['status'])
qb.reportjob(agenda['status'])
log('worker shutting down')
return
# Waiting; relatively rare, try again shortly.
elif agenda['status'] == 'waiting':
timeout = 10 # seconds
log('job %s is waiting for %ds' % (job['id'], timeout))
time.sleep(timeout)
continue
package_to_print = dict(agenda['package'])
package_to_print.pop('__pickle__', None)
log('work package')
pprint.pprint(package_to_print)
print '# ---'
# Prepare some pipes for communicating with the subprocess.
request_pipe = os.pipe()
response_pipe = os.pipe()
# Open the process, doing a dev bootstrap if this is a dev environment.
# We are calling this module, which will end up calling the
# :func:`execute` function.
cmd = []
if 'VEE_EXEC_ARGS' in os.environ or 'KS_DEV_ARGS' in os.environ:
# These both have a "dev" command with a "--bootstrap" which do
# the same thing.
cmd.extend(('dev', '--bootstrap'))
cmd.extend((
agenda['package'].get('interpreter', 'python'),
'-m', 'qbfutures.sandbox.the_corner',
str(request_pipe[0]), str(response_pipe[1]),
))
log('spawning child: %s' % subprocess.list2cmdline(cmd))
proc = subprocess.Popen(cmd, close_fds=False)
# Close our end of the pipes so that there is only one process which
# still has them open (the child).
os.close(request_pipe[0])
os.close(response_pipe[1])
# Send the job and agenda package to the child.
with os.fdopen(request_pipe[1], 'w') as request_fh:
pickle.dump(job_for_child, request_fh, -1)
pickle.dump(agenda['package'], request_fh, -1)
# Get the response from the child.
with os.fdopen(response_pipe[0], 'r') as response_fh:
try:
package = pickle.load(response_fh)
except Exception as e:
traceback.print_exc()
sys.stderr.flush()
package = {
'status': 'failed',
'exception': e,
}
# Wait for the child to finish.
# log('waiting for child...')
proc.wait()
package.setdefault('status', 'failed')
agenda['resultpackage'] = utils.pack(package)
agenda['status'] = package['status']
log('work resultpackage')
pprint.pprint(package)
print '# ---'
if agenda['status'] == 'failed':
log('os.environ')
for k, v in sorted(os.environ.iteritems()):
print '# %s = %r' % (k, v)
print '# ---'
log('reporting work as %s' % agenda['status'])
qb.reportwork(agenda)
def executeJob(control):
'''
Execute the transcoding process.
'''
jobstate = 'pending'
qbJob = control.getQubeJobObject()
if not control.checkForErrors():
while 1:
agendaItem = qb.requestwork()
returnCode = 1
'''
First Handle non-running state cases
'''
if agendaItem['status'] in ('complete', 'pending', 'blocked', 'waiting'):
'''
complete -- no more frames
pending -- preempted, so bail out
blocked -- perhaps item is part of a dependency
'''
jobstate = agendaItem['status']
logger.info('Job %s state is now %s' % (qbJob['id'], jobstate))
break
'''
Run the transcoding process that corresponds to the agendaItem name.
Initialize
Setup the blender scene.
Segment
Transcode a segment of frames.
Final Output
Merge that output's segments together with audio.
'''
if agendaItem['name'] == 'Initialize':
logger.info('Initializing...\n')
if os.path.exists(control.getBlendFile()):
logger.info("Initialization script alread exists.")
returnCode = 0
else:
returnCode = runCMD(control.getInitCMD(agendaItem))
if returnCode == 0:
logger.info('Initialization Complete! (' + str(returnCode) + ')\n')
else:
logger.error('Initialization Failed! (' + str(returnCode) + ')\n')
elif agendaItem['name'].startswith('Segment'):
'''
Segment Process:
> Make sure the blender project was created
> Load the segment frame range from the work package.
> Check for missing frames in the segments frame range.
True
> Report an error and end the subjob
False
> Continue with transcode
> Check if smartUpdate is turned on.
True
> Check if the Modification Times Database and the output file exists.
True
> Check if there have been modifications to any frames in this segment.
True
> Continue with transcode
False
> Skip transcoding
> Check if we are still transcoding.
True
> Try to Remove output file if it already exists
Success
> Transcode
Failure
> Add '_' to the output file name and try again until sucess.
Max retry is 3 times, then fail the subjob.
> Check if smartUpdate is turned on.
True
> Update the modification times database
False
> Continue
> Update the resultPackage with whether changes were made and the segment output file.
'''
logger.info("Starting Transcoder Segment Process...")
render = False
error = False
''' Check for the blender project '''
if not os.path.exists(control.getBlendFile()):
logger.error('Blender Project doesn\'t exist.')
error = True
else:
''' Load the frame range from the work package '''
frameRangeString = agendaItem['package']['frameRange']
logging.debug("FrameRangeString: %s" % frameRangeString)
frameRange = sequenceTools.loadFrameRange(frameRangeString)
logging.debug("Loaded frameRange: %s" % frameRange)
''' Check for Missing Frames '''
mySequence = control.getSequence()
missingFrames = mySequence.getMissingFrames(frameRange)
if len(missingFrames) > 0:
logger.error('Missing frames!\n' + ','.join(missingFrames))
error = True
else:
logger.info('No Missing Frames')
if not error:
''' Variables used multiple times '''
segmentFilePath = agendaItem.setdefault('package', {}).get('segmentFile', '')
segmentFileExists = os.path.exists(segmentFilePath)
currentModTimes = {}
modTimeDBFile = control.getModTimeDBFile()
if control.getSmartUpdate():
modTimeDBFileExists = os.path.exists(modTimeDBFile)
logger.debug('Segment Output: ' + str(segmentFilePath))
logger.debug('Segment Exists: ' + str(segmentFileExists))
logger.debug('ModTimeDBFile: ' + str(modTimeDBFile))
logger.debug('ModTimeDBFile Exists: ' + str(modTimeDBFileExists))
if segmentFileExists and modTimeDBFileExists:
logger.info('Smart Updating')
logger.debug('Loading current modification times...')
currentModTimes = mySequence.getModTimes(frameRange)
logger.debug('Current modication times loaded. %s' % currentModTimes)
logger.debug('Comparing modification times for frame range %s...' % frameRange)
compare = mySequence.compare(modTimeDBFile, frameRange, currentModTimes=currentModTimes)
logger.debug('Sequence Differences: %s' % str(compare))
differences = ''
if len(compare['Added']) > 0:
frameNumbers = mySequence.getFramesFromFilenames(compare['Added'])
differences += '\n\tAdded: %s' % mySequence.convertListToRanges(frameNumbers)
if len(compare['Deleted']) > 0:
frameNumbers = mySequence.getFramesFromFilenames(compare['Deleted'])
differences += '\n\tDeleted: %s' % mySequence.convertListToRanges(frameNumbers)
if len(compare['Modified']) > 0:
frameNumbers = mySequence.getFramesFromFilenames(compare['Modified'])
differences += '\n\tModified: %s' % mySequence.convertListToRanges(frameNumbers)
if differences:
logger.info('Sequence Differences: %s' % differences)
render = True
else:
render = True
else:
render = True
if render:
segmentFilePath = control.getValidOutputPath(segmentFilePath)
if segmentFilePath:
render = True
else:
error = True
if render:
logger.info('Transcoding Segment %s' % agendaItem['name'])
cmd = control.getSegmentCMD(agendaItem)
returnCode = runCMD(cmd)
logger.info('Transcoding Segment Complete! (' + str(returnCode) + ')')
if control.getSmartUpdate():
logger.debug("Saved ModTimes: " + str(currentModTimes))
control.job.sequence.saveModTimes(modTimeDBFile,
modTimeDict=currentModTimes, frameRange=frameRange)
logger.info("Saved Modification Times")
else:
if not error:
logger.info("No changes to segment " + agendaItem['name'])
returnCode = 0
'''
Check if this is the last agenda item that's complete.
If so, unblock the final output subjobs.
'''
agendaItem['resultpackage'] = {'Changed': render, 'segmentFile': segmentFilePath}
logger.info("Transcoder Segment Process Complete!\n")
elif agendaItem['name'].startswith('Output'):
'''
Final Output Process
> Gather the output paths and changes for all of the segments
stored in their resultPackages.
> Check if there were changes.
True
> Continue Transcoding
False
> Skip Trancoding
> Load segmentOutputPaths from the agenda
> Check if segmentPaths exist.
True
> Continue Transcoding
False
> Skip Transcoding with error
> Check if output path is valid
True
> Continue Transcoding
False
> Skip Transcoding with error
> Check if we are still transcoding.
True
> Concatenate segments together.
False
> Skip
> Update the resultPackage with the outputPath.
'''
logger.info("Starting Final Output Process...\n")
transcode = False
errors = False
dependantNames = agendaItem.get('package', {}).get('segmentSubjobs', '')
logger.debug('Dependants Names: ' + str(dependantNames))
dependantSegments = control.getSegments(dependantNames)
logger.debug('Dependants Segments: ' + str(dependantSegments))
finalOutputPath = agendaItem['package']['outputFile']
if finalOutputPath:
transcode = True
else:
errors = True
if transcode:
changes = control.checkSegmentsForChanges(dependantSegments)
if not changes:
logger.info("No changes to segments.")
if os.path.exists(str(finalOutputPath)):
logger.info('Final output movie already exists. ' + str(finalOutputPath))
returnCode = 0
transcode = False
else:
logger.info('Final output movie doesn\'t exist. ' + str(finalOutputPath))
transcode = True
else:
transcode = True
if transcode:
segmentOutputPaths = control.getSegmentOutputPaths(dependantSegments)
if segmentOutputPaths:
transcode = True
else:
errors = True
if transcode:
startFrame = control.getOutputStartFrame(dependantSegments)
logger.debug('Output Start Frame: ' + startFrame)
if transcode:
finalOutputPath = control.getValidOutputPath(finalOutputPath)
if finalOutputPath:
transcode = True
else:
errors = True
if transcode:
cmd = control.getFinalOutputCMD(segmentOutputPaths, finalOutputPath, startFrame, 29.97, agendaItem)
returnCode = runCMD(cmd)
if returnCode != 0:
errors = True
else:
logger.info('No changes to Final ' + agendaItem['name'])
if not errors:
agendaItem['resultpackage'] = {'outputPaths': finalOutputPath}
logger.info('Transcoder Final ' + agendaItem['name'] + ' Completed Succesfully! (' + str(returnCode) + ')\n')
else:
logger.info('Transcoder Final ' + agendaItem['name'] + ' Failed!' + str(returnCode) + ')\n')
else:
logger.error("Invalid Agenda Item")
logger.error(str(agendaItem))
'''
Update the work status based on the return code.
'''
if returnCode == 0:
agendaItem['status'] = 'complete'
else:
agendaItem['status'] = 'failed'
''' Report back the results to the Supervisor '''
qb.reportwork(agendaItem)
if jobstate == 'blocked':
jobstate = 'pending'
return jobstate