nuke disappears = deadline thinks its complete

LaszloSebo · October 28, 2013, 6:49pm

It seems that if nuke disappears for any reason (lets say it crashes, or is killed from the task manager), deadline thinks its finished the frame. There doesnt seem to be any safety checks for a ‘success’ printout, or something like that…

For example:

2013-10-28 11:18:59: 0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/Vectorfield.dll 2013-10-28 11:18:59: 0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/Light2.dll 2013-10-28 11:18:59: 0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/BlackOutside.dll 2013-10-28 11:18:59: 0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/STMap.dll 2013-10-28 11:18:59: 0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/Sharpen.dll 2013-10-28 11:19:00: 0: STDOUT: [11:18:59 Pacific Daylight Time] Read nuke script: //inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048_tbo.nk 2013-10-28 11:19:00: 0: STDOUT: Mon Oct 28 11:19:00 2013 (+19183ms) :(localizeReads): Localizing nodes... 2013-10-28 11:23:24: 0: INFO: Process exit code: 0 2013-10-28 11:23:24: 0: Render time for frame(s): 5.224 m 2013-10-28 11:23:24: 0: Total time for task: 5.259 m

A real frame looks like this:

2013-10-28 11:18:16:  0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/Light2.dll
2013-10-28 11:18:16:  0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/BlackOutside.dll
2013-10-28 11:18:16:  0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/STMap.dll
2013-10-28 11:18:16:  0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/Sharpen.dll
2013-10-28 11:18:16:  0: STDOUT: [11:18:16 Pacific Daylight Time] Read nuke script: //inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048_tbo.nk
2013-10-28 11:18:16:  0: STDOUT: Mon Oct 28 11:18:16 2013 (+1940ms)  :(localizeReads): Localizing nodes...
2013-10-28 11:21:24:  0: STDOUT: Mon Oct 28 11:21:24 2013 (+187806ms) :(localizeReads): Pruning nodes outside render graph...
2013-10-28 11:21:24:  0: STDOUT: Mon Oct 28 11:21:24 2013 (+38ms)    :(localizeReads): Localize Stats:
2013-10-28 11:21:24:  0: STDOUT: Mon Oct 28 11:21:24 2013 (+0ms)     :(localizeReads):  - Write Nodes Processed: WriteBot4
2013-10-28 11:21:24:  0: STDOUT: Mon Oct 28 11:21:24 2013 (+0ms)     :(localizeReads):  - Input Nodes Processed: 52
2013-10-28 11:21:24:  0: STDOUT: Mon Oct 28 11:21:24 2013 (+0ms)     :(localizeReads):  - Paths Localized: 202
2013-10-28 11:21:24:  0: STDOUT: Mon Oct 28 11:21:24 2013 (+0ms)     :(localizeReads):  - Localization Time: 183.194999933 seconds
2013-10-28 11:21:43:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1175.exr 
2013-10-28 11:21:44:  0: STDOUT: RotoPaint1 .9
2013-10-28 11:21:44:  0: STDOUT: OFlow1 
2013-10-28 11:21:48:  0: STDOUT: Processing :  .1.9
2013-10-28 11:21:53:  0: STDOUT: RotoPaint3 .9
2013-10-28 11:21:53:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1175.exr took 28.18 seconds
2013-10-28 11:21:53:  0: STDOUT: Frame 1175 (1 of 4)
2013-10-28 11:22:11:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1176.exr 
2013-10-28 11:22:12:  0: STDOUT: RotoPaint1 .9
2013-10-28 11:22:12:  0: STDOUT: OFlow1 
2013-10-28 11:22:20:  0: STDOUT: Processing :  .9
2013-10-28 11:22:20:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1176.exr took 27.15 seconds
2013-10-28 11:22:21:  0: STDOUT: Frame 1176 (2 of 4)
2013-10-28 11:22:40:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1177.exr .9
2013-10-28 11:22:40:  0: STDOUT: OFlow1 
2013-10-28 11:22:47:  0: STDOUT: Processing :  .9
2013-10-28 11:22:47:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1177.exr took 26.77 seconds
2013-10-28 11:22:47:  0: STDOUT: Frame 1177 (3 of 4)
2013-10-28 11:23:07:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1178.exr .9
2013-10-28 11:23:07:  0: STDOUT: OFlow1 
2013-10-28 11:23:14:  0: STDOUT: Processing :  .9
2013-10-28 11:23:14:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.1178.exr took 26.77 seconds
2013-10-28 11:23:14:  0: STDOUT: Frame 1178 (4 of 4)
2013-10-28 11:23:14:  0: STDOUT: Total render time: 1 minute, 49 seconds
2013-10-28 11:23:14:  0: STDOUT: Allocated 7.98GiB, 25% of usage limit of 32GiB.
2013-10-28 11:23:14:  0: STDOUT: free_*() calls: 0, new_handler() cleanups: 0.

Then there are debug prints for the ram usage
then more

2013-10-28 11:23:14:  0: STDOUT: Loading //s2/exchange/software/Nuke/projects/wolf/NAD/NAD_210_0400/VIEWER_INPUT.gizmo
2013-10-28 11:23:14:  0: STDOUT: Loading C:/Program Files/Nuke7.0v8/plugins/jpegWriter.dll
2013-10-28 11:23:25:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1175.jpg .1
2013-10-28 11:23:25:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1175.jpg took 10.42 seconds
2013-10-28 11:23:25:  0: STDOUT: Frame 1175 (1 of 1)
2013-10-28 11:23:25:  0: STDOUT: Total render time: 10 seconds
2013-10-28 11:23:25:  0: STDOUT: .9
2013-10-28 11:23:26:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1176.jpg .6
2013-10-28 11:23:26:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1176.jpg took 0.58 seconds
2013-10-28 11:23:26:  0: STDOUT: Frame 1176 (1 of 1)
2013-10-28 11:23:26:  0: STDOUT: Total render time: 0.58 seconds
2013-10-28 11:23:26:  0: STDOUT: .9
2013-10-28 11:23:26:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1177.jpg 
2013-10-28 11:23:26:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1177.jpg took 0.46 seconds
2013-10-28 11:23:26:  0: STDOUT: Frame 1177 (1 of 1)
2013-10-28 11:23:26:  0: STDOUT: Total render time: 0.46 seconds
2013-10-28 11:23:26:  0: STDOUT: .9
2013-10-28 11:23:26:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1178.jpg .9
2013-10-28 11:23:26:  0: STDOUT: Writing S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/proxy_2kwfana/NAD_210_0400_comp_v0048.1178.jpg took 0.51 seconds
2013-10-28 11:23:27:  0: STDOUT: Frame 1178 (1 of 1)
2013-10-28 11:23:27:  0: STDOUT: Total render time: 0.51 seconds
2013-10-28 11:24:00:  0: STDOUT: "-F": argument not used
2013-10-28 11:24:00:  0: STDOUT: Set filename: S:/nuke_cache/inferno2/projects/wolf/scenes/NAD_210_0400/2d/comps/NAD_210_0400_comp_v0048/linear_2kwfana/NAD_210_0400_comp_v0048.%04d.exr
2013-10-28 11:24:00:  0: STDOUT: starting output transfer
2013-10-28 11:24:00:  0: STDOUT: No QIDs in Args. Skipping any transfers.
2013-10-28 11:24:00:  0: STDOUT: tagging all elements as dependent...
2013-10-28 11:24:00:  0: STDOUT:     dependency publish completed.
2013-10-28 11:24:01:  0: INFO: Process exit code: 0
2013-10-28 11:24:01:  0: Render time for frame(s): 5.881 m
2013-10-28 11:24:01:  0: Total time for task: 5.900 m

rrussell · October 28, 2013, 7:18pm

Do these Nuke jobs have the BatchMode option set to True in the plugin info file?

BatchMode=True

In this mode, we launch Nuke in a batch mode similar to how the 3dsmax plugin works. If Nuke craps out, it should be detected that Nuke exited unexpectedly and the appropriate error should be thrown.

We should probably update our Nuke plugin to default this to True, since we already default it to True in the Nuke submitters we ship with Deadline.

LaszloSebo · October 28, 2013, 9:51pm

We are not using batch mode currently, but that sounds pretty good actually.

Two questions about that:

does nuke restart between different jobs if they are both batchmode? (we need it to restart, cause each job might have a different environment)
is there any kind of pre-frame callback function we could use? we are doing localization for nuke jobs, and it only localizes the frames required for the render, before the nuke file is even opened. If deadline then feeds it new frames, those would be missing (so we would basically just need to trigger localization for each task)

LaszloSebo · October 29, 2013, 1:17am

Disregard this particular issue of not marking things properly failed, our nuke.py has been customized to ignore errors … we were monitoring the process return code previously, but in batch mode, that does not work (as the process never quits). We removed the error handlers because in some cases nuke prints ‘error’ in the log, even when its not an error.

The rest of the questions still stand

rrussell · October 29, 2013, 1:38pm

Yes. Like the 3dsmax plugin, Nuke will be restarted between jobs, but kept open for subsequent tasks from the same job.

There isn’t, but I guess you could force Deadline to restart Nuke between each task by setting this in your job info file:

ForceReloadPlugin=True

But then you basically lose the benefits of keeping Nuke open between tasks, other than the monitoring of the Nuke process for unexpected exits.

Also, I think you has posted that your “on close” callbacks weren’t getting called. I had checked our Nuke plugin, and we were just calling quit() when stopping Nuke. For beta 9, we first call nuke.scriptClose() before calling quit(), so your “on close” callbacks should now be called when Nuke exits. If you need it to run for every task, forcing Deadline to restart Nuke between each task should accomplish that as well.

Cheers,

Ryan

LaszloSebo · October 29, 2013, 3:50pm

Thanks for adding that to beta9!

Would be good to have a pre-task callback somewhere (could we maybe customize that nuke.py plugin to get that functionality?), as the benefits of keeping nuke & job open are great!

rrussell · October 29, 2013, 7:22pm

Yeah, you guys should be able to customize nuke.py to achieve this. All we’re doing is piping python into Nuke’s stdin, so you should just have to do something similar in the RenderTasks function.

LaszloSebo · October 30, 2013, 9:46pm

It seems that if we are not running nuke in batch mode, some last lines in the stdout are not being put in the log. For example, if nuke is unable to rename the tmp files its rendering into to the final filename, thats usually marked by an error such as: “Can’t rename .tmp to final”. These are only printed in the deadline log (and thus handled as an error) in batch mode.

Nuke quits right after this image… is the stdout maybe not flushed?

l

rrussell · October 31, 2013, 2:31pm

What we can do is try to flush stdout from the rendering process one last time before we check its exit code. That last check should hopefully ensure we get every last bit of stdout from the process. We’ll do this in beta 10, and hopefully it makes a difference.

Cheers,

Ryan