Houdini, 19.5 FailRenderException : Error: Caught exception: The attempted operation failed

casey · July 20, 2023, 4:39pm

I’m getting this error currently while testing my setup.

The job will eventually complete, but not without throwing this error a random number of times.

FailRenderException : Error: Caught exception: The attempted operation failed.

=======================================================
Error
=======================================================
FailRenderException : Error: Caught exception: The attempted operation failed.
   at Deadline.Plugins.DeadlinePlugin.FailRender(String message) (Python.Runtime.PythonException)
  File "C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\plugins\64b95d7405066881d31eaf0a\Houdini.py", line 410, in HandleStdoutError
    self.FailRender(self.GetRegexMatch(1))
   at Python.Runtime.Dispatcher.Dispatch(ArrayList args)
   at __FranticX_Processes_ManagedProcess_StdoutHandlerDelegateDispatcher.Invoke()
   at FranticX.Processes.ManagedProcess.RegexHandlerCallback.CallFunction()
   at FranticX.Processes.ManagedProcess.e(String dl, Boolean dm)
   at FranticX.Processes.ManagedProcess.Execute(Boolean waitForExit)
   at Deadline.Plugins.DeadlinePlugin.DoRenderTasks()
   at Deadline.Plugins.PluginWrapper.RenderTasks(Task task, String& outMessage, AbortLevel& abortLevel)
   at Deadline.Plugins.PluginWrapper.RenderTasks(Task task, String& outMessage, AbortLevel& abortLevel)

=======================================================
Type
=======================================================
RenderPluginException

=======================================================
Stack Trace
=======================================================
   at Deadline.Plugins.SandboxedPlugin.d(DeadlineMessage bgq, CancellationToken bgr)
   at Deadline.Plugins.SandboxedPlugin.RenderTask(Task task, CancellationToken cancellationToken)
   at Deadline.Slaves.SlaveRenderThread.c(TaskLogWriter ajv, CancellationToken ajw)

=======================================================
Log
=======================================================
2023-07-20 09:14:46:  0: Loading Job's Plugin timeout is Disabled
2023-07-20 09:14:46:  0: SandboxedPlugin: Render Job As User disabled, running as current user 'xcase'
2023-07-20 09:14:47:  0: Executing plugin command of type 'Initialize Plugin'
2023-07-20 09:14:47:  0: INFO: Executing plugin script 'C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\plugins\64b95d7405066881d31eaf0a\Houdini.py'
2023-07-20 09:14:47:  0: INFO: Plugin execution sandbox using Python version 3
2023-07-20 09:14:47:  0: INFO: About: Houdini Plugin for Deadline
2023-07-20 09:14:47:  0: INFO: The job's environment will be merged with the current environment before rendering
2023-07-20 09:14:47:  0: Done executing plugin command of type 'Initialize Plugin'
2023-07-20 09:14:47:  0: Start Job timeout is disabled.
2023-07-20 09:14:47:  0: Task timeout is disabled.
2023-07-20 09:14:47:  0: Loaded job: HALCYON_TUR_SCENE_001 - /obj/ODFX_OCTQuickSetup2022/ropnet1/Octane_ROP1 (64b95d7405066881d31eaf0a)
2023-07-20 09:14:47:  0: Executing plugin command of type 'Start Job'
2023-07-20 09:14:47:  0: DEBUG: S3BackedCache Client is not installed.
2023-07-20 09:14:47:  0: INFO: Executing global asset transfer preload script 'C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\plugins\64b95d7405066881d31eaf0a\GlobalAssetTransferPreLoad.py'
2023-07-20 09:14:47:  0: INFO: Looking for legacy (pre-10.0.26) AWS Portal File Transfer...
2023-07-20 09:14:47:  0: INFO: Looking for legacy (pre-10.0.26) File Transfer controller in C:/Program Files/Thinkbox/S3BackedCache/bin/task.py...
2023-07-20 09:14:47:  0: INFO: Could not find legacy (pre-10.0.26) AWS Portal File Transfer.
2023-07-20 09:14:47:  0: INFO: Legacy (pre-10.0.26) AWS Portal File Transfer is not installed on the system.
2023-07-20 09:14:47:  0: Done executing plugin command of type 'Start Job'
2023-07-20 09:14:47:  0: Plugin rendering frame(s): 1
2023-07-20 09:14:47:  0: Executing plugin command of type 'Render Task'
2023-07-20 09:14:47:  0: INFO: Set HOUDINI_PATHMAP to {"/Users/caseyhupke/Dropbox":"D:/Dropbox", "D:/Dropbox":"D:/Dropbox", "/Volumes/Dropbox":"D:/Dropbox"}
2023-07-20 09:14:47:  0: INFO: Redshift Path Mapping...
2023-07-20 09:14:47:  0: INFO: source: "/Users/caseyhupke/Dropbox" dest: "D:\Dropbox"
2023-07-20 09:14:47:  0: INFO: source: "D:\Dropbox" dest: "D:\Dropbox"
2023-07-20 09:14:47:  0: INFO: source: "/Volumes/Dropbox" dest: "D:\Dropbox"
2023-07-20 09:14:47:  0: INFO: [REDSHIFT_PATHOVERRIDE_FILE] now set to: "C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\jobsData\64b95d7405066881d31eaf0a\RSMapping_temppfEHw0\RSMapping.txt"
2023-07-20 09:14:47:  0: INFO: Starting Houdini Job
2023-07-20 09:14:47:  0: INFO: Stdout Redirection Enabled: True
2023-07-20 09:14:47:  0: INFO: Stdout Handling Enabled: True
2023-07-20 09:14:47:  0: INFO: Popup Handling Enabled: True
2023-07-20 09:14:47:  0: INFO: QT Popup Handling Enabled: False
2023-07-20 09:14:47:  0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False
2023-07-20 09:14:47:  0: INFO: Using Process Tree: True
2023-07-20 09:14:47:  0: INFO: Hiding DOS Window: True
2023-07-20 09:14:47:  0: INFO: Creating New Console: False
2023-07-20 09:14:47:  0: INFO: Running as user: xcase
2023-07-20 09:14:47:  0: INFO: Executable: "C:\Program Files\Side Effects Software\Houdini 19.5.640\bin\hython.exe"
2023-07-20 09:14:47:  0: CheckPathMapping: Swapped "/Volumes/Dropbox/_root/_lab/HALCYON.AI/HFX/PRODUCT/HALCYON_TUR_SCENE_001.hip" with "D:\Dropbox/_root/_lab/HALCYON.AI/HFX/PRODUCT/HALCYON_TUR_SCENE_001.hip"
2023-07-20 09:14:47:  0: INFO: Argument: "C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\plugins\64b95d7405066881d31eaf0a\hrender_dl.py" -f 1 1 1 -o "$HIP/render/test.$F4.exr" -g -d /obj/ODFX_OCTQuickSetup2022/ropnet1/Octane_ROP1 -tempdir "C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\jobsData\64b95d7405066881d31eaf0a\0_tempXYnpu0" -arnoldAbortOnLicenseFail 1 "D:/Dropbox/_root/_lab/HALCYON.AI/HFX/PRODUCT/HALCYON_TUR_SCENE_001.hip"
2023-07-20 09:14:47:  0: INFO: Full Command: "C:\Program Files\Side Effects Software\Houdini 19.5.640\bin\hython.exe" "C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\plugins\64b95d7405066881d31eaf0a\hrender_dl.py" -f 1 1 1 -o "$HIP/render/test.$F4.exr" -g -d /obj/ODFX_OCTQuickSetup2022/ropnet1/Octane_ROP1 -tempdir "C:\ProgramData\Thinkbox\Deadline10\workers\BAHAMUT\jobsData\64b95d7405066881d31eaf0a\0_tempXYnpu0" -arnoldAbortOnLicenseFail 1 "D:/Dropbox/_root/_lab/HALCYON.AI/HFX/PRODUCT/HALCYON_TUR_SCENE_001.hip"
2023-07-20 09:14:47:  0: INFO: Startup Directory: "C:\Program Files\Side Effects Software\Houdini 19.5.640\bin"
2023-07-20 09:14:47:  0: INFO: Process Priority: BelowNormal
2023-07-20 09:14:47:  0: INFO: Process Affinity: default
2023-07-20 09:14:47:  0: INFO: Process is now running
2023-07-20 09:14:49:  0: STDOUT: [Octane]      Octane Render for Houdini. Build 2022.1.1.1 (Build date: Jun 12 2023 18:51:01)
2023-07-20 09:14:49:  0: STDOUT: [Octane] Octane API: 2022.1.1
2023-07-20 09:14:49:  0: STDOUT: [Octane] HDK API: 19.5.605
2023-07-20 09:14:49:  0: STDOUT: [Octane] Houdini host version: 19.5.640
2023-07-20 09:14:49:  0: STDOUT: [Octane] Initializing Octane API
2023-07-20 09:14:49:  0: STDOUT: [Octane] Octane API ready. Initialization time: 1.003 seconds
2023-07-20 09:14:49:  0: STDOUT: [Octane] OCIO configuration ready. Initialization time: 0.045 seconds
2023-07-20 09:14:49:  0: STDOUT: [Octane] Octane network rendering enabled. Initialization time: 0.000 seconds
2023-07-20 09:14:49:  0: STDOUT: [Octane] Loading preferences from: C:/Users/xcase/OneDrive/Documents/houdini19.5/octane.pref
2023-07-20 09:14:49:  0: STDOUT: 09:14:49 INFOR: [nodes] -------------  Registering Octane VOP nodes
2023-07-20 09:14:49:  0: STDOUT: [Octane] 09:14:49 INFOR: [nodes] -------------  Registering Octane VOP nodes
2023-07-20 09:14:49:  0: STDOUT: 09:14:49 INFOR: [nodes] -------------  Octane VOP nodes registered
2023-07-20 09:14:49:  0: STDOUT: [Octane] 09:14:49 INFOR: [nodes] -------------  Octane VOP nodes registered
2023-07-20 09:14:49:  0: STDOUT: 09:14:49 INFOR: [nodes] -------------  Registering the plugin custom VOP nodes
2023-07-20 09:14:49:  0: STDOUT: [Octane] 09:14:49 INFOR: [nodes] -------------  Registering the plugin custom VOP nodes
2023-07-20 09:14:49:  0: STDOUT: 09:14:49 INFOR: [nodes] -------------  Plugin custom VOP nodes registered
2023-07-20 09:14:50:  0: STDOUT: [Octane] 09:14:49 INFOR: [nodes] -------------  Plugin custom VOP nodes registered
2023-07-20 09:14:50:  0: STDOUT: Detected Houdini version: (19, 5, 640)
2023-07-20 09:14:50:  0: STDOUT: ['C:\\ProgramData\\Thinkbox\\Deadline10\\workers\\BAHAMUT\\plugins\\64b95d7405066881d31eaf0a\\hrender_dl.py', '-f', '1', '1', '1', '-o', '$HIP/render/test.$F4.exr', '-g', '-d', '/obj/ODFX_OCTQuickSetup2022/ropnet1/Octane_ROP1', '-tempdir', 'C:\\ProgramData\\Thinkbox\\Deadline10\\workers\\BAHAMUT\\jobsData\\64b95d7405066881d31eaf0a\\0_tempXYnpu0', '-arnoldAbortOnLicenseFail', '1', 'D:/Dropbox/_root/_lab/HALCYON.AI/HFX/PRODUCT/HALCYON_TUR_SCENE_001.hip']
2023-07-20 09:14:50:  0: STDOUT: Start: 1
2023-07-20 09:14:50:  0: STDOUT: End: 1
2023-07-20 09:14:50:  0: STDOUT: Increment: 1
2023-07-20 09:14:50:  0: STDOUT: Ignore Inputs: True
2023-07-20 09:14:50:  0: STDOUT: Output: $HIP/render/test.$F4.exr
2023-07-20 09:14:50:  0: STDOUT: Driver: /obj/ODFX_OCTQuickSetup2022/ropnet1/Octane_ROP1
2023-07-20 09:14:50:  0: STDOUT: Input File: D:/Dropbox/_root/_lab/HALCYON.AI/HFX/PRODUCT/HALCYON_TUR_SCENE_001.hip
2023-07-20 09:14:50:  0: Done executing plugin command of type 'Render Task'

=======================================================
Details
=======================================================
Date: 07/20/2023 09:14:54
Frames: 1
Elapsed Time: 00:00:00:08
Job Submit Date: 07/20/2023 09:14:43
Job User: caseyhupke
Average RAM Usage: 23545114624 (35%)
Peak RAM Usage: 23545114624 (35%)
Average CPU Usage: 2%
Peak CPU Usage: 18%
Used CPU Clocks (x10^6 cycles): 10983
Total CPU Clocks (x10^6 cycles): 549124

=======================================================
Worker Information
=======================================================
Worker Name: BAHAMUT
Version: v10.2.1.1 Release (094cbe890)
Operating System: Windows 11 Pro
Running As Service: No
Machine User: xcase
IP Address: 192.168.1.34
MAC Address: D8:5E:D3:84:13:EB
CPU Architecture: x64
CPUs: 32
CPU Usage: 0%
Memory Usage: 21.9 GB / 63.8 GB (34%)
Free Disk Space: 2.341 TB (425.145 GB on C:\, 1.254 TB on D:\, 687.725 GB on E:\)
Video Card: Parsec Virtual Display Adapter

Justin_B · July 20, 2023, 8:06pm

It’s hard to say, our error handling tends to cut off the text of the error in cases like these.

Could you use the guide to isolate Houdini renders to run this away from our error handling?

That should let us see what operation is failing, thanks!

casey · July 30, 2023, 3:52pm

I ended up solving it by forcing everything into the project directory. Even though every path was resolving correctly when it was remapped. Working now!

fabiaserra · February 9, 2024, 4:19am

we were getting lots of these hidden errors and it was making it very painful to have to run locally to figure out what was going on. I ended up commenting out these lines in the Houdini plugin and now it’s working wonderfully:

        self.AddStdoutHandlerCallback( "(Error: .*)" ).HandleCallback += self.HandleStdoutError
        self.AddStdoutHandlerCallback(r"(ERROR\s*\|.*)").HandleCallback += self.HandleStdoutError #Arnold errors
        self.AddStdoutHandlerCallback(r"\[Error\].*").HandleCallback += self.HandleStdoutError

I can see the actual errors in the monitor! I think that Hython is already returning non-zero exit codes when it errors out so I don’t think those regexes are important but I will report back if this bugs us again, for now I way rather get the error logs than non catched errors!

Ahmed_Hindy · October 9, 2024, 10:11am

@fabiaserra did you encounter any errors or strange behaviors when you commented out those lines?

mois.moshev · October 9, 2024, 10:22am

Indeed it works without this error detection, due to the return codes.
We took an “opposite” approach, and have a whitelist of messages that do not fail the jobs.
It’s a bit unfortunate that Deadline stops the job after detecting the first error in stdout.

fabiaserra · October 9, 2024, 2:01pm

It did yes! I haven’t encountered any limitations by taking this approach yet (mind we aren’t very busy lately)