AddStdoutHandler executed in what order?

phudson1442 · March 21, 2011, 5:43pm

Hi,
We have an issue where Nuke sometimes completes a task but then hangs. To get around it for now, I added a StdOutHandler to match “Total render time:” and ExitWithSuccess()

So we now having the following StdOutHandlers

self.AddStdoutHandler( ".*ERROR:.*", self.HandleError ) self.AddStdoutHandler( ".*Error:.*", self.HandleError ) self.AddStdoutHandler( ".* seconds to execute", self.HandleProgress ) self.AddStdoutHandler( ".* took [0-9]*\\.[0-9]* seconds", self.HandleProgress ) self.AddStdoutHandler( "Total render time:.*", self.HandleComplete )

[code] def HandleError( self ):
LogInfo( "Detected Error: " + self.GetRegexMatch( 0 ))
FailRender( self.GetRegexMatch( 0 ) )

def HandleComplete( self ):
	LogInfo( "Detected Task Completion (Whiskytree): " + self.GetRegexMatch( 0 ) )
	SetStatusMessage( "Detected Task Completion: " + self.GetRegexMatch( 0 ) )
	ExitWithSuccess()[/code]

The problem is the “Total render time:” match seems to be preempting the matches for “ERROR:”/“Error:”

For example:

0: STDOUT: Loading C:/Program Files/Nuke6.1v2/plugins/Log2Lin.dll 0: STDOUT: Loading C:/Program Files/Nuke6.1v2/plugins/Vectorfield.dll 0: STDOUT: Loading C:/Program Files/Nuke6.1v2/plugins/Colorspace.dll 0: STDOUT: Loading C:/Program Files/Nuke6.1v2/plugins/objReader.dll 0: STDOUT: [13:06.51] ERROR: Read5: Cannot read image file "X:/show/dev/AA/1000/rndr/AA_1000_lighting_CMAP/CMAP_f1280_left/v018/CMAP_f1280_left_Main/CMAP_f1280_left_Main_v018.1227.exr". Too many open files. 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read5: X:/show/dev/AA/1000/rndr/AA_1000_lighting_CMAP/CMAP_f1280_left/v018/CMAP_f1280_left_Main/CMAP_f1280_left_Main_v018.1227.exr: Reader did not set channels 0: STDOUT: [13:06.51] ERROR: Read5: X:/show/dev/AA/1000/rndr/AA_1000_lighting_CMAP/CMAP_f1280_left/v018/CMAP_f1280_left_Main/CMAP_f1280_left_Main_v018.1227.exr: Reader did not set channels 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read5: X:/show/dev/AA/1000/rndr/AA_1000_lighting_CMAP/CMAP_f1280_left/v018/CMAP_f1280_left_Main/CMAP_f1280_left_Main_v018.1227.exr: Reader did not set bounding box 0: STDOUT: [13:06.51] ERROR: Read5: X:/show/dev/AA/1000/rndr/AA_1000_lighting_CMAP/CMAP_f1280_left/v018/CMAP_f1280_left_Main/CMAP_f1280_left_Main_v018.1227.exr: Reader did not set bounding box 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read36: Cannot read image file "X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/FG_volume_left/v018/FG_volume_left_Main/FG_volume_left_Main_v018.1036.exr". Too many open files. 0: STDOUT: [13:06.51] ERROR: Read36: Cannot read image file "X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/FG_volume_left/v018/FG_volume_left_Main/FG_volume_left_Main_v018.1036.exr". Too many open files. 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read36: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/FG_volume_left/v018/FG_volume_left_Main/FG_volume_left_Main_v018.1036.exr: Reader did not set channels 0: STDOUT: [13:06.51] ERROR: Read36: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/FG_volume_left/v018/FG_volume_left_Main/FG_volume_left_Main_v018.1036.exr: Reader did not set channels 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read36: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/FG_volume_left/v018/FG_volume_left_Main/FG_volume_left_Main_v018.1036.exr: Reader did not set bounding box 0: STDOUT: [13:06.51] ERROR: Read36: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/FG_volume_left/v018/FG_volume_left_Main/FG_volume_left_Main_v018.1036.exr: Reader did not set bounding box 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read16: Cannot read image file "X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/BG_volume_left/v018/BG_volume_left_Main/BG_volume_left_Main_v018.1036.exr". Too many open files. 0: STDOUT: [13:06.51] ERROR: Read16: Cannot read image file "X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/BG_volume_left/v018/BG_volume_left_Main/BG_volume_left_Main_v018.1036.exr". Too many open files. 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read16: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/BG_volume_left/v018/BG_volume_left_Main/BG_volume_left_Main_v018.1036.exr: Reader did not set channels 0: STDOUT: [13:06.51] ERROR: Read16: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/BG_volume_left/v018/BG_volume_left_Main/BG_volume_left_Main_v018.1036.exr: Reader did not set channels 0: WARNING: Another error occurred in regex function: [13:06.51] ERROR: Read16: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/BG_volume_left/v018/BG_volume_left_Main/BG_volume_left_Main_v018.1036.exr: Reader did not set bounding box 0: STDOUT: [13:06.51] ERROR: Read16: X:/show/dev/AA/1000/rndr/AA_1000_lighting_tree/BG_volume_left/v018/BG_volume_left_Main/BG_volume_left_Main_v018.1036.exr: Reader did not set bounding box 0: INFO: Detected Task Completion: Total render time: 6.40 seconds

As you can see, “Total render time:” is matched even after 5 or 6 lines with “ERROR:” in them. Shouldn’t FailRender() have already been called?! Why are the Errors not being matched.

Is “Another error occurred in regex function” coming from Nuke or Deadline?

Thanks,
Paul

MikeOwen · March 21, 2011, 7:24pm

I think the “Reader did not set channels” bit of the log is indicating that something is not correct in the channels that are being passed between 2 or more nodes in your Nuke comp.
My money is on something not being quite right in your Nuke comp.
Can you post the Nuke script?
HTH,
Mike

phudson1442 · March 21, 2011, 8:44pm

The error in this case is the Nuke/Windows issue “Too many open files”. Once this issue happens, you’ll get a ton of different errors at Read nodes, Copy nodes, etc. That’s a whole other nightmare, but the thing that is critical to me at the moment is why Deadline is not seeing the “ERROR:” output. I want it to match that and call FailRender(). Otherwise, it makes it to the end of the log output and matches “Total render time:” and calls ExitWithSuccess().

To solve one problem, I’ve created a different problem… but this is happening because Deadline isn’t behaving as I expected.

eamsler · March 22, 2011, 8:29pm

Ryan should be back tomorrow to shed some light on this. For now I’m not really sure what’s going on there either.

rrussell · March 23, 2011, 5:11am

I’m not in the office yet to confirm this, but I’m wondering if the ExitWithSuccess() is overriding the FailRender(). Maybe try something like this to see if it helps:

   ErrorOccurred = False

   def HandleError( self ):
      LogInfo( "Detected Error: " + self.GetRegexMatch( 0 ))
      self.ErrorOccurred = True
      FailRender( self.GetRegexMatch( 0 ) )

   def HandleComplete( self ):
      if not self.ErrorOccurred:
         LogInfo( "Detected Task Completion (Whiskytree): " + self.GetRegexMatch( 0 ) )
         SetStatusMessage( "Detected Task Completion: " + self.GetRegexMatch( 0 ) )
         ExitWithSuccess()

Then in the Nuke plug-in’s PreRenderTasks function, you would reset “ErrorOccurred” to False.

Cheers,

Ryan