We’re encountering this and a few other problems with Fusion 9.0.1 and Deadline 10.0.4.2 on Windows 10.
I did a fresh uninstall/reinstall of Fusion and the Fusion Render Node on my local machine for testing to be sure it’s got 9.0.1 in case there were problems they’ve fixed since 9.0.
The first problem I see in the log is this:
2017-11-17 10:52:06: 0: Could not kill process with name fuscript because: Access is denied (System.ComponentModel.Win32Exception)
Windows task manager shows both with status “Running” and User name “SYSTEM”. The Deadline slave is running under user accounts, not as a system service, and we do not have Render Job As User set. Are we meant to set something on these exe’s or or in Windows somewhere to allow Deadline to kill these?
2017-11-17 14:07:55: 0: Plugin will be reloaded because a new job has been loaded.
2017-11-17 14:07:55: 0: Loading Job's Plugin timeout is Disabled
2017-11-17 14:07:56: 0: Loaded plugin Fusion
2017-11-17 14:07:56: 0: Executing plugin command of type 'Sync Files for Job'
2017-11-17 14:07:56: 0: All job files are already synchronized
2017-11-17 14:07:56: 0: Plugin Fusion was already synchronized.
2017-11-17 14:07:56: 0: Done executing plugin command of type 'Sync Files for Job'
2017-11-17 14:07:57: 0: Executing plugin command of type 'Initialize Plugin'
2017-11-17 14:07:57: 0: INFO: Executing plugin script 'C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\plugins\5a0e20566c5b76093421c9d6\Fusion.py'
2017-11-17 14:07:57: 0: INFO: About: Fusion Plugin for Deadline
2017-11-17 14:07:57: 0: INFO: Render Job As User disabled, running as current user 'mplec'
2017-11-17 14:07:57: 0: INFO: The job's environment will be merged with the current environment before rendering
2017-11-17 14:07:57: 0: Done executing plugin command of type 'Initialize Plugin'
2017-11-17 14:07:57: 0: Start Job timeout is disabled.
2017-11-17 14:07:57: 0: Task timeout is disabled.
2017-11-17 14:07:57: 0: Loaded job: fusion 9 test (5a0e20566c5b76093421c9d6)
2017-11-17 14:07:57: 0: Executing plugin command of type 'Start Job'
2017-11-17 14:07:57: 0: INFO: Executing global job preload script 'C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\plugins\5a0e20566c5b76093421c9d6\GlobalJobPreLoad.py'
2017-11-17 14:07:57: 0: INFO: Looking for AWS Portal File Transfer...
2017-11-17 14:07:57: 0: INFO: Looking for File Transfer controller in C:/Program Files/Thinkbox/S3BackedCache/bin/task.py...
2017-11-17 14:07:57: 0: INFO: Could not find AWS Portal File Transfer.
2017-11-17 14:07:57: 0: INFO: AWS Portal File Transfer is not installed on the system.
2017-11-17 14:07:58: 0: INFO: ScriptExecutable 'C:\Program Files\Blackmagic Design\Fusion Render Node 9\fuscript.exe' is already running, attempting to kill it.
2017-11-17 14:07:58: 0: Could not kill process with name fuscript because: Access is denied (System.ComponentModel.Win32Exception)
2017-11-17 14:07:59: 0: Could not kill process with name fuscript because: Access is denied (System.ComponentModel.Win32Exception)
[...]
2017-11-17 15:51:33: 0: Could not kill process with name fuscript because: Access is denied (System.ComponentModel.Win32Exception)
2017-11-17 15:51:34: 0: Could not kill process with name fuscript because: Access is denied (System.ComponentModel.Win32Exception)
2017-11-17 15:51:35: 0: Done executing plugin command of type 'Start Job'
2017-11-17 15:51:35: 0: An exception occurred: Error: Could not terminate existing ScriptExecutable process fuscript.exe
2017-11-17 15:51:35: at Deadline.Plugins.PluginWrapper.StartJob(String& outMessage, AbortLevel& abortLevel) (Deadline.Plugins.RenderPluginException)
2017-11-17 15:51:35: 0: Unloading plugin: Fusion
2017-11-17 15:51:37: Scheduler Thread - Render Thread 0 threw a major error:
2017-11-17 15:51:37: >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2017-11-17 15:51:37: Exception Details
2017-11-17 15:51:37: RenderPluginException -- Error: Could not terminate existing ScriptExecutable process fuscript.exe
2017-11-17 15:51:37: at Deadline.Plugins.PluginWrapper.StartJob(String& outMessage, AbortLevel& abortLevel)
2017-11-17 15:51:37: RenderPluginException.Cause: JobError (2)
2017-11-17 15:51:37: RenderPluginException.Level: Major (1)
2017-11-17 15:51:37: RenderPluginException.HasSlaveLog: True
2017-11-17 15:51:37: RenderPluginException.SlaveLogFileName: C:\ProgramData\Thinkbox\Deadline10\logs\deadlineslave_renderthread_0-nvr-vfx-mplec-0000.log
2017-11-17 15:51:37: Exception.Data: ( )
2017-11-17 15:51:37: Exception.TargetSite: Deadline.Slaves.Messaging.PluginResponseMemento SendMessageToSandbox(Deadline.Net.DeadlineMessage)
2017-11-17 15:51:37: Exception.Source: deadline
2017-11-17 15:51:37: Exception.HResult: -2146233088
2017-11-17 15:51:37: Exception.StackTrace:
2017-11-17 15:51:37: at Deadline.Plugins.SandboxedPlugin.SendMessageToSandbox(DeadlineMessage messageToSend)
2017-11-17 15:51:37: at Deadline.Plugins.SandboxedPlugin.StartJob(Job job)
2017-11-17 15:51:37: at Deadline.Slaves.SlaveRenderThread.RenderCurrentTask(TaskLogWriter tlw)
2017-11-17 15:51:37: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
(Note that I added the log line about attempting to kill it to see which one it’s on before it times out and gives the fail message.)
Even if I kill them manually from the task manager (which doesn’t require me to elevate to admin) they reappear a moment later and when I retry the task, as soon as the task gets into the starting state the log issues the failure to kill messages again. As far as I can tell from the Windows task manager Services panel, the fusion server get installed to startup at login and restart if it fails.
I commented out the bit of Fusion.py that does the check and kill on self.scriptExecutable and retried the task…
Now I get the problems Makoto Chiba is encountering:
SCRIPT ERROR: eyeonScript made a connection in StartJon.eyeonscript but fusion failed to get a license and finish setup in time
If I run stuff manually from the dos cmd prompt, first:
"C:\Program Files\Blackmagic Design\Fusion Render Node 9\FusionRenderNode.exe" /quiet /listen /verbose /log "C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\jobsData\5a0e20566c5b76093421c9d6\fusionLog_tempqbTAw0\fusion.log"
and then:
"C:\Program Files\Blackmagic Design\Fusion Render Node 9\fuscript.exe" "C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\plugins\5a0e20566c5b76093421c9d6\StartJob.eyeonscript" "C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\jobsData\5a0e20566c5b76093421c9d6\thread0_temp4ocxz0\arnold5_simple_vr_comp.comp" 30
I get the same StartJon error and nothing is printed to the log running the fuscript.exe after the last bit from the node startup (“Initialising Scripting Subsystem”). “fuscript” indeed.
Here’s what I get stepping through StartupJob.eyeonscript manually:
[code]C:\Users\mplec>“C:\Program Files\Blackmagic Design\Fusion Render Node 9\fuscript.exe” -i
Fusion Script Interpreter
Copyright © 2005 - 2017 Blackmagic Design Pty. Ltd.
Lua> df = Fusion(“127.0.0.1”)
Lua> print(df)
FusionUI (0x0000000000582030) [App: ‘Fusion’ on 127.0.0.1, UUID: 8f3b5a34-ed85-48ab-8801-4d40cb954824]
Lua> print(df.CurrentComp)
nil
Lua> io.flush()
Lua> fl = df:GetCompList()
Lua> for i=1, table.getn(fl) do
Lua>> print( "STARTJOB: Closing comp " … i )
Lua>> io.flush()
Lua>> fl[i]:Close()
Lua>> end
Lua>
Lua> print(table.getn(fl))
0
Lua> comp = df:LoadComp(“C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\jobsData\5a0e20566c5b76093421c9d6\thread0_temp4ocxz0\arnold5_simple_vr_comp.comp”, true)
Lua> print(comp)
Composition (0x000000000960EC00) [App: ‘Fusion’ on 127.0.0.1, UUID: 8f3b5a34-ed85-48ab-8801-4d40cb954824]
Lua> comp:Lock()
[/code]
That all looks ok so I removed the check for df.CurrentComp and retried the job but it failed with:
2017-11-17 19:06:25: 0: STDOUT: SCRIPT ERROR: Fusion failed to load the comp 'C:\Users\mplec\AppData\Local\Thinkbox\Deadline10\slave\nvr-vfx-mplec\jobsData\5a0e20566c5b76093421c9d6\thread0_templB0Vw0\arnold5_simple_vr_comp.comp'. This could be due to a missing or incompatible plugin.
So I put a few more prints in and df:LoadComp( arg[1], true ) is returning nil.
However, when I start the render node manually from the cmd prompt and then run the fuscript.exe with the same script it loads the comp ok.
I’m stumped for now so I’ll leave it here in case this rings bells for anyone and see if anything looks different Monday.