I rolled Back to H18.5 to debug UBL issues.
…this is strange. when UBL checks out a license, it relies on these files below, but they have bad permissions. The only way this would work for someone else is if deadline is running as root, which we shouldn’t be doing. So I’m following best practice here by running deadline as a dedicated user, but obviously the permissions are wrong, or the process trying to access the file is not the same user that created the file.
On my render node running Centos 7:
[deadlineuser@ip-10-1-142-176 Deadline10]$ ll
total 16
drwxr-xr-x. 2 root root 33 Jun 10 10:09 cert
-rwxrwxrwx. 1 nobody nobody 301 Jun 10 10:08 dconf.bin
-rwxrwxrwx. 1 nobody nobody 553 Jun 10 10:08 deadline.ini
-rw-rw-r-- 1 deadlineuser deadlineuser 34 Jun 10 12:35 hserverAddress
-rw-rw-r–. 1 deadlineuser deadlineuser 44 Jun 10 12:27 launcher.ini
drwxrwxrwx. 2 nobody nobody 18 Jun 10 10:09 slaves
drwxrwxrwx. 4 nobody nobody 53 Jun 10 12:28 workers
[deadlineuser@ip-10-1-142-176 Deadline10]$ cat ./hserverAddress
/opt/hfs18.5/bin/hserver
127.0.0.1[deadlineuser@ip-10-1-142-176 Deadline10]$
2022-06-10 12:32:13: 0: STDOUT: PDG_RESULT: ropfetch_ondemand_byo_license_6;3;/Volumes/cloud_prod/temp/geo/test.deadline.v017.test_pdg_ubl_h18.5.rop_geometry_single.4.bgeo.sc;;0
2022-06-10 12:32:13: 0: STDOUT: PDG_SUCCESS: ropfetch_ondemand_byo_license_6;3;0
2022-06-10 12:32:20: 0: Done executing plugin command of type ‘Render Task’
2022-06-10 12:32:24: 0: RenderThread CancelCurrentTask called, will transition from state None to None
2022-06-10 12:32:25: 0: Executing plugin command of type ‘Cancel Task’
2022-06-10 12:32:25: 0: Done executing plugin command of type ‘Cancel Task’
2022-06-10 12:32:25: 0: Executing plugin command of type ‘End Job’
2022-06-10 12:32:25: 0: Done executing plugin command of type ‘End Job’
2022-06-10 12:32:27: Sending kill command to process deadlinesandbox.exe with id: 2507
2022-06-10 12:33:48: Port Forwarder (houdini:1715): Port forwarder created.
2022-06-10 12:33:48: PYTHON: Settings Address to ‘127.0.0.1’. Prev Address is Login | SideFX
2022-06-10 12:33:48: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-10 12:33:48: Worker - Confirmed Credit Usage for “houdini”.
2022-06-10 12:34:55: ERROR: Scheduler Thread - Unexpected Error Occurred
2022-06-10 12:34:55: Scheduler Thread - CalledProcessError : Command ‘[’/opt/hfs18.5/bin/hserver’, ‘-S’, ‘127.0.0.1’]’ returned non-zero exit status 1. (FranticX.Scripting.PythonNetException)
2022-06-10 12:34:55: Port Forwarder (houdini:1715): Port Forwarder shutting down.
2022-06-10 12:34:56: PYTHON: Unable to restore previous environment. Could not find path: ‘/var/lib/Thinkbox/Deadline10/hserverAddress’
2022-06-10 12:34:56: PYTHON: May have been removed by another Houdini or Mantra Usage Based Limit.
2022-06-10 12:35:09: Port Forwarder (houdini:1715): Port forwarder created.
2022-06-10 12:35:09: PYTHON: Settings Address to ‘127.0.0.1’. Prev Address is 127.0.0.1
2022-06-10 12:35:10: Message From License Forwarder: Success: Machine registered (ip-10-1-142-176/::ffff:10.1.142.176).
2022-06-10 12:35:10: Scheduler Thread - Job’s Limit Groups: engine_ubl
2022-06-10 12:35:10: 0: Loading Job’s Plugin timeout is Disabled
2022-06-10 12:35:10: 0: WARNING: Python version for ‘PDGDeadline’ plugin is not specified! Defaulting to Python 2.
2022-06-10 12:35:10: 0: SandboxedPlugin: Render Job As User disabled, running as current user ‘deadlineuser’
2022-06-10 12:35:12: ‘/home/deadlineuser/Thinkbox/Deadline10/pythonAPIs/2IhDVvfZG2KHEck6rDemog==’ already exists. Skipping extraction of PythonSync.
2022-06-10 12:35:13: All job files are already synchronized
2022-06-10 12:35:13: Synchronizing Plugin PDGDeadline from /Volumes/cloud_prod/temp/pdgtemp/66492/plugins/PDGDeadline took: 0 seconds
2022-06-10 12:35:14: 0: Executing plugin command of type ‘Initialize Plugin’
2022-06-10 12:35:14: 0: INFO: Executing plugin script ‘/var/lib/Thinkbox/Deadline10/workers/ip-10-1-142-176/plugins/62a33a226ff1b91611e22357/PDGDeadline.py’
2022-06-10 12:35:14: 0: INFO: Plugin execution sandbox using Python version 2
I have no explanation for this, but it seems that this on startup user data is inadequate:
sudo -i -u $deadlineuser_name bash -c "cd /opt/hfs$houdini_major_version && source ./houdini_setup && hserver"
…And yet this variant resolves the permissions issues !!!
sudo -i -u $deadlineuser_name bash -c "cd /opt/hfs$houdini_major_version && source ./houdini_setup && hserver ; sleep 10 ; hserver ; hserver -S https://www.sidefx.com/license/sesinetd ; hserver -l"
My only guess is that the 10 second delay and running hserver twice is somehow doing something.
But @thinkbox isn’t it odd that we have to run hserver at all in user data? Thats an assumption of the software that seems unnecesary, and Deadline should simply start it if it is not already started.
1 Like
The remaining mystery is why does the first process starting up on a new ondemand instance with UBL have some socket related issue? The subsequent process seems to continue ok, but still I have a need to eliminate the exception. Subsequent processes seem ok. The error is the same with the Thinkbox Deadline Rop on a new instance.
Should I be concerned that I am seeing a “Win32Exception” on the deadline DB / license forwarder node running Ubuntu? Only the submitter workstation is running windows.
Connecting to ip-10-1-136-140...
RemoteLog: connecting to machine '10.1.136.140' which resolved to '10.1.136.140' port 37263
Making a connection to '10.1.136.140' port 37263
2022-06-11 14:14:36: Purging old logs and temp files
Success
2022-06-11 14:16:10: Port Forwarder (houdini:1715): Port forwarder created.
2022-06-11 14:16:10: PYTHON: Settings Address to '127.0.0.1'. Prev Address is https://www.sidefx.com/license/sesinetd
2022-06-11 14:16:10: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-11 14:16:10: Worker - Confirmed Credit Usage for "houdini".
2022-06-11 14:16:10: >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022-06-11 14:16:10: Exception Details
2022-06-11 14:16:10: ExtendedSocketException -- Connection refused 10.1.128.12:1715
2022-06-11 14:16:10: SocketException.SocketErrorCode: ConnectionRefused (10061)
2022-06-11 14:16:10: SocketException.ErrorCode: 111 (Connection refused)
2022-06-11 14:16:10: Win32Exception.NativeErrorCode: 111
2022-06-11 14:16:10: Exception.TargetSite: Void DoConnect(System.Net.EndPoint, System.Net.Internals.SocketAddress)
2022-06-11 14:16:10: Exception.Data: ( )
2022-06-11 14:16:10: Exception.Source: System.Net.Sockets
2022-06-11 14:16:10: Exception.HResult: -2147467259
2022-06-11 14:16:10: Exception.StackTrace:
2022-06-11 14:16:10: at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress
2022-06-11 14:16:10: at System.Net.Sockets.Socket.Connect(EndPoint remoteEP
2022-06-11 14:16:10: at System.Net.Sockets.Socket.Connect(IPAddress address, Int32 port
2022-06-11 14:16:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port)
2022-06-11 14:16:10: --- End of stack trace from previous location where exception was thrown --
2022-06-11 14:16:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port
2022-06-11 14:16:10: at System.Net.Sockets.TcpClient..ctor(String hostname, Int32 port
2022-06-11 14:16:10: at Deadline.Net.PortForwarder.b(Socket bhu)
2022-06-11 14:16:10: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022-06-11 14:16:10: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-11 14:16:10: >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022-06-11 14:16:10: Exception Details
2022-06-11 14:16:10: ExtendedSocketException -- Connection refused 10.1.128.12:1715
2022-06-11 14:16:10: SocketException.SocketErrorCode: ConnectionRefused (10061)
2022-06-11 14:16:10: SocketException.ErrorCode: 111 (Connection refused)
2022-06-11 14:16:10: Win32Exception.NativeErrorCode: 111
2022-06-11 14:16:10: Exception.TargetSite: Void DoConnect(System.Net.EndPoint, System.Net.Internals.SocketAddress)
2022-06-11 14:16:10: Exception.Data: ( )
2022-06-11 14:16:10: Exception.Source: System.Net.Sockets
2022-06-11 14:16:10: Exception.HResult: -2147467259
2022-06-11 14:16:10: Exception.StackTrace:
2022-06-11 14:16:10: at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress
2022-06-11 14:16:10: at System.Net.Sockets.Socket.Connect(EndPoint remoteEP
2022-06-11 14:16:10: at System.Net.Sockets.Socket.Connect(IPAddress address, Int32 port
2022-06-11 14:16:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port)
2022-06-11 14:16:10: --- End of stack trace from previous location where exception was thrown --
2022-06-11 14:16:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port
2022-06-11 14:16:10: at System.Net.Sockets.TcpClient..ctor(String hostname, Int32 port
2022-06-11 14:16:10: at Deadline.Net.PortForwarder.b(Socket bhu)
2022-06-11 14:16:10: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022-06-11 14:16:10: Message From License Forwarder: Success: Machine registered (ip-10-1-136-140/::ffff:10.1.136.140).
2022-06-11 14:16:10: Scheduler Thread - Job's Limit Groups: engine_ubl
2022-06-11 14:16:11: 0: Loading Job's Plugin timeout is Disabled
2022-06-11 14:16:11: 0: WARNING: Python version for 'PDGDeadline' plugin is not specified! Defaulting to Python 2.
2022-06-11 14:16:11: 0: SandboxedPlugin: Render Job As User disabled, running as current user 'deadlineuser'
2022-06-11 14:16:12: '/home/deadlineuser/Thinkbox/Deadline10/pythonAPIs/2IhDVvfZG2KHEck6rDemog==' already exists. Skipping extraction of PythonSync.
2022-06-11 14:16:14: All job files are already synchronized
2022-06-11 14:16:14: Synchronizing Plugin PDGDeadline from /Volumes/cloud_prod/temp/pdgtemp/67072/plugins/PDGDeadline took: 0 seconds
2022-06-11 14:16:15: 0: Executing plugin command of type 'Initialize Plugin'
2022-06-11 14:16:15: 0: INFO: Executing plugin script '/var/lib/Thinkbox/Deadline10/workers/ip-10-1-136-140/plugins/62a4a3a004664d5bf7e7d5d3/PDGDeadline.py'
2022-06-11 14:16:15: 0: INFO: Plugin execution sandbox using Python version 2
2022-06-11 14:16:15: 0: INFO: *********** PDGDeadline InitializeProcess
2022-06-11 14:16:15: 0: INFO: About: PDG Plugin for Deadline
2022-06-11 14:16:15: 0: INFO: The job's environment will be merged with the current environment before rendering
2022-06-11 14:16:15: 0: Done executing plugin command of type 'Initialize Plugin'
2022-06-11 14:16:15: 0: Start Job timeout is disabled.
2022-06-11 14:16:15: 0: Task timeout is disabled.
2022-06-11 14:16:15: 0: Loaded job: PDG TASKS (62a4a3a004664d5bf7e7d5d3)
2022-06-11 14:16:15: 0: Executing plugin command of type 'Start Job'
2022-06-11 14:16:15: 0: DEBUG: S3BackedCache Client is not installed.
2022-06-11 14:16:15: 0: INFO: Executing global asset transfer preload script '/var/lib/Thinkbox/Deadline10/workers/ip-10-1-136-140/plugins/62a4a3a004664d5bf7e7d5d3/GlobalAssetTransferPreLoad.py'
2022-06-11 14:16:16: 0: INFO: Looking for legacy (pre-10.0.26) AWS Portal File Transfer...
2022-06-11 14:16:16: 0: INFO: Looking for legacy (pre-10.0.26) File Transfer controller in /opt/Thinkbox/S3BackedCache/bin/task.py...
2022-06-11 14:16:16: 0: INFO: Could not find legacy (pre-10.0.26) AWS Portal File Transfer.
2022-06-11 14:16:16: 0: INFO: Legacy (pre-10.0.26) AWS Portal File Transfer is not installed on the system.
2022-06-11 14:16:16: 0: Done executing plugin command of type 'Start Job'
2022-06-11 14:16:16: 0: Plugin rendering frame(s): 0
2022-06-11 14:16:16: 0: Executing plugin command of type 'Render Task'
2022-06-11 14:16:16: 0: INFO: StartFrame: 0
2022-06-11 14:16:16: 0: INFO: Startup Directory: /Volumes/cloud_prod/temp/pdgtemp/67072
2022-06-11 14:16:16: 0: INFO: Looking for task file: /Volumes/cloud_prod/temp/pdgtemp/67072/job_ae81b5f956dd4ef2adf26c113c1adda0/task_0.txt
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable HFS to /opt/hfs18.5
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_HTTP_PORT to
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_SHARED_TEMP to /Volumes/cloud_prod/temp/pdgtemp/67072
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_DIR to /Volumes/cloud_prod/temp
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable HOUDINI_MAXTHREADS to 0
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_RESULT_CLIENT_ID to fd62e9ed350a4a8e8d242467fc401fc8
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_SCRIPTDIR to /Volumes/cloud_prod/temp/pdgtemp/67072/scripts
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_MQ_CONN_FILE to /Volumes/cloud_prod/temp/pdgtemp/67072/job_ae81b5f956dd4ef2adf26c113c1adda0/pdgmq_server.txt
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_DISABLE_TIMESTAMPS to 1
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_USE_PDGNET to 1
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_PATHMAP to {"paths":[{"X:/":{"path":"/Volumes/cloud_prod/","zone":"LINUX"}},{"$HFS":{"path":"/opt/hfs18.5","zone":"LINUX"}},{"C:/Program Files/Side Effects Software/Houdini 19.0.589":{"path":"/opt/hfs18.5","zone":"LINUX"}},{"C:/Program Files/Side Effects Software/Houdini 19.0.589":{"path":"/opt/hfs18.5","zone":"LINUX"}},{"C:/PROGRA~1/SIDEEF~1/HOUDIN~1.589":{"path":"/opt/hfs18.5","zone":"LINUX"}},{"X:/temp":{"path":"/Volumes/cloud_prod/temp","zone":"LINUX"}},{"/Volumes/cloud_prod":{"path":"X:/","zone":"WIN"}}]}
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable HOUDINI_PATH to /Volumes/cloud_prod/temp/pdgtemp/67072;&
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_TEMP to /Volumes/cloud_prod/temp/pdgtemp/67072
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_RESULT_SERVER to
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_BREAKAWAY_FROM_JOB to 1
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_JOBID to DL_JOB_ID
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_JOBID_VAR to PDG_JOBID
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_RELEASE_SLOT_ON_POLL to 0
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_HFS to /opt/hfs18.5
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_DELOCALIZE to 0
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_JOBUSE_PDGNET to 1
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_PYATTRIB_LOADER to
2022-06-11 14:16:16: 0: INFO: Setting os PATH with HFS: /usr/lib64/qt-3.3/bin:/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/deadlineuser/.local/bin:/home/deadlineuser/bin:/bin:/usr/bin:/sbin:/bin:/usr/bin:/bin:/usr/bin:/opt/hfs18.5/bin
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PATH to /usr/lib64/qt-3.3/bin:/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/deadlineuser/.local/bin:/home/deadlineuser/bin:/bin:/usr/bin:/sbin:/bin:/usr/bin:/bin:/usr/bin:/opt/hfs18.5/bin
2022-06-11 14:16:16: 0: INFO: $HYTHON mapped to: /opt/hfs18.5/bin/hython
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_TEMP to /Volumes/cloud_prod/temp/pdgtemp/67072
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_SHARED_TEMP to /Volumes/cloud_prod/temp/pdgtemp/67072
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_SCRIPTDIR to /Volumes/cloud_prod/temp/pdgtemp/67072/scripts
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_DIR to /Volumes/cloud_prod/temp
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_HFS to /opt/hfs18.5
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PYTHON to
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_JOBID to 62a4a3a004664d5bf7e7d5d3
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_JOB_BATCH_NAME to PDG test.deadline.v017.test_pdg_ubl_h18.5 2022-06-11 23:45:45.540006
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_ITEM_NAME to ropfetch_ondemand_ubl_51
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_INDEX to 0
2022-06-11 14:16:16: 0: INFO: Submit as job: False
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_SUBMIT_AS_JOB to False
2022-06-11 14:16:16: 0: INFO: Waiting for MQ connection file /Volumes/cloud_prod/temp/pdgtemp/67072/job_ae81b5f956dd4ef2adf26c113c1adda0/pdgmq_server.txt
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_RESULT_SERVER to 192.168.82.13:59716
2022-06-11 14:16:16: 0: INFO: PDG_RESULT_SERVER: 192.168.82.13:59716
2022-06-11 14:16:16: 0: INFO: Setting Process Environment Variable PDG_HTTP_PORT to 59718
2022-06-11 14:16:16: 0: INFO: PDG_HTTP_PORT: 59718
2022-06-11 14:16:16: 0: INFO: Task Executable: /opt/hfs18.5/bin/hython
2022-06-11 14:16:16: 0: INFO: Task Arguments: "/Volumes/cloud_prod/temp/pdgtemp/67072/scripts/rop.py" "json"
2022-06-11 14:16:16: 0: INFO: Invoking: Run Process
2022-06-11 14:18:18: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'houdini' which was previously imported from '/opt/hfs18.5/houdini/pdg/types/houdini'. Module will be skipped.
2022-06-11 14:18:18: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'partitioners' which was previously imported from '/opt/hfs18.5/houdini/pdg/types/partitioners'. Module will be skipped.
2022-06-11 14:18:18: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'schedulers' which was previously imported from '/opt/hfs18.5/houdini/pdg/types/schedulers'. Module will be skipped.
2022-06-11 14:18:18: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'utils' which was previously imported from '/opt/hfs18.5/houdini/pdg/types/utils'. Module will be skipped.
2022-06-11 14:18:20: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-11 14:18:21: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-11 14:18:23: 0: STDOUT: Running Houdini 18.5.968 with PID 8906
2022-06-11 14:18:23: 0: STDOUT: PDG: Pathmap Zone LINUX with 6 mappings for this zone.
2022-06-11 14:18:23: 0: STDOUT: Loading .hip file /Volumes/cloud_prod/temp/test.deadline.v017.test_pdg_ubl_h18.5.hip.
2022-06-11 14:18:29: 0: STDOUT: Cooking ROP node '/obj/sphere_object1/rop_geometry_single'
2022-06-11 14:18:29: 0: STDOUT: ROP type name: 'rop_geometry'
2022-06-11 14:18:29: 0: STDOUT: ROP source path: 'Internal'
2022-06-11 14:18:29: 0: STDOUT: Checking for custom output parms '[u'sopoutput']' on node '/obj/sphere_object1/rop_geometry_single'
2022-06-11 14:18:29: 0: STDOUT: Setting callback postwrite on /obj/sphere_object1/rop_geometry_single
2022-06-11 14:18:29: 0: STDOUT: Setting callback preframe on /obj/sphere_object1/rop_geometry_single
2022-06-11 14:18:29: 0: STDOUT: Cooking node using 'hou.Rop.render'
2022-06-11 14:18:29: 0: STDOUT: Setting batch sub index to 0
2022-06-11 14:18:29: 0: STDOUT: Checking for custom output parms '[u'sopoutput']' on node '/obj/sphere_object1/rop_geometry_single'
2022-06-11 14:18:29: 0: STDOUT: PDG_START: ropfetch_ondemand_ubl_51;0
2022-06-11 14:18:30: 0: STDOUT: ALF_PROGRESS 0%
2022-06-11 14:18:30: 0: STDOUT: Setting batch sub index to 1
2022-06-11 14:18:30: 0: STDOUT: PDG_START: ropfetch_ondemand_ubl_51;1
2022-06-11 14:18:30: 0: STDOUT: ALF_PROGRESS 33%
2022-06-11 14:18:30: 0: STDOUT: Setting batch sub index to 2
2022-06-11 14:18:30: 0: STDOUT: PDG_START: ropfetch_ondemand_ubl_51;2
2022-06-11 14:18:30: 0: STDOUT: ALF_PROGRESS 67%
2022-06-11 14:18:30: 0: STDOUT: postFrame 0
2022-06-11 14:18:30: 0: STDOUT: PDG_RESULT: ropfetch_ondemand_ubl_51;0;/Volumes/cloud_prod/temp/geo/test.deadline.v017.test_pdg_ubl_h18.5.rop_geometry_single.1.bgeo.sc;;0
2022-06-11 14:18:31: 0: STDOUT: PDG_SUCCESS: ropfetch_ondemand_ubl_51;0;0
2022-06-11 14:18:31: 0: STDOUT: postFrame 1
2022-06-11 14:18:31: 0: STDOUT: PDG_RESULT: ropfetch_ondemand_ubl_51;1;/Volumes/cloud_prod/temp/geo/test.deadline.v017.test_pdg_ubl_h18.5.rop_geometry_single.2.bgeo.sc;;0
2022-06-11 14:18:31: 0: STDOUT: PDG_SUCCESS: ropfetch_ondemand_ubl_51;1;0
2022-06-11 14:18:32: 0: STDOUT: Setting batch sub index to 3
2022-06-11 14:18:32: 0: STDOUT: PDG_START: ropfetch_ondemand_ubl_51;3
2022-06-11 14:18:32: 0: STDOUT: ALF_PROGRESS 100%
2022-06-11 14:18:32: 0: STDOUT: postFrame 2
2022-06-11 14:18:32: 0: STDOUT: PDG_RESULT: ropfetch_ondemand_ubl_51;2;/Volumes/cloud_prod/temp/geo/test.deadline.v017.test_pdg_ubl_h18.5.rop_geometry_single.3.bgeo.sc;;0
2022-06-11 14:18:32: 0: STDOUT: PDG_SUCCESS: ropfetch_ondemand_ubl_51;2;0
2022-06-11 14:18:33: 0: STDOUT: postFrame 3
2022-06-11 14:18:33: 0: STDOUT: PDG_RESULT: ropfetch_ondemand_ubl_51;3;/Volumes/cloud_prod/temp/geo/test.deadline.v017.test_pdg_ubl_h18.5.rop_geometry_single.4.bgeo.sc;;0
2022-06-11 14:18:33: 0: STDOUT: PDG_SUCCESS: ropfetch_ondemand_ubl_51;3;0
2022-06-11 14:18:37: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-11 14:18:37: 0: Done executing plugin command of type 'Render Task'
2022-06-11 14:18:44: 0: RenderThread CancelCurrentTask called, will transition from state None to None
2022-06-11 14:18:44: 0: Executing plugin command of type 'Cancel Task'
2022-06-11 14:18:44: 0: Done executing plugin command of type 'Cancel Task'
2022-06-11 14:18:44: 0: Executing plugin command of type 'End Job'
2022-06-11 14:18:44: 0: Done executing plugin command of type 'End Job'
2022-06-11 14:18:46: Sending kill command to process deadlinesandbox.exe with id: 8870
It seems to be related to whenever the license forwarder needs to start a new request for a license. The changeover causes an exception, and then subsequently works.
This happens with the deadline Rop and with PDG in both 18.5 and H19. It’s problematic to see these exceptions because I rely on automated tests that don’t produce errors to know that the infra is functional for all the code responsible for the deployment.
Connecting to ip-10-1-141-99...
RemoteLog: connecting to machine '10.1.141.99' which resolved to '10.1.141.99' port 44919
Making a connection to '10.1.141.99' port 44919
2022-06-12 13:28:44: Purging old logs and temp files
Success
2022-06-12 13:31:10: Port Forwarder (houdini:1715): Port forwarder created.
2022-06-12 13:31:10: PYTHON: Settings Address to '127.0.0.1'. Prev Address is https://www.sidefx.com/license/sesinetd
2022-06-12 13:31:10: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-12 13:31:10: Worker - Confirmed Credit Usage for "houdini".
2022-06-12 13:31:10: >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022-06-12 13:31:10: Exception Details
2022-06-12 13:31:10: ExtendedSocketException -- Connection refused 10.1.128.12:1715
2022-06-12 13:31:10: SocketException.SocketErrorCode: ConnectionRefused (10061)
2022-06-12 13:31:10: SocketException.ErrorCode: 111 (Connection refused)
2022-06-12 13:31:10: Win32Exception.NativeErrorCode: 111
2022-06-12 13:31:10: Exception.TargetSite: Void DoConnect(System.Net.EndPoint, System.Net.Internals.SocketAddress)
2022-06-12 13:31:10: Exception.Data: ( )
2022-06-12 13:31:10: Exception.Source: System.Net.Sockets
2022-06-12 13:31:10: Exception.HResult: -2147467259
2022-06-12 13:31:10: Exception.StackTrace:
2022-06-12 13:31:10: at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress
2022-06-12 13:31:10: at System.Net.Sockets.Socket.Connect(EndPoint remoteEP
2022-06-12 13:31:10: at System.Net.Sockets.Socket.Connect(IPAddress address, Int32 port
2022-06-12 13:31:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port)
2022-06-12 13:31:10: --- End of stack trace from previous location where exception was thrown --
2022-06-12 13:31:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port
2022-06-12 13:31:10: at System.Net.Sockets.TcpClient..ctor(String hostname, Int32 port
2022-06-12 13:31:10: at Deadline.Net.PortForwarder.b(Socket bhu)
2022-06-12 13:31:10: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022-06-12 13:31:10: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-12 13:31:10: >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022-06-12 13:31:10: Exception Details
2022-06-12 13:31:10: ExtendedSocketException -- Connection refused 10.1.128.12:1715
2022-06-12 13:31:10: SocketException.SocketErrorCode: ConnectionRefused (10061)
2022-06-12 13:31:10: SocketException.ErrorCode: 111 (Connection refused)
2022-06-12 13:31:10: Win32Exception.NativeErrorCode: 111
2022-06-12 13:31:10: Exception.TargetSite: Void DoConnect(System.Net.EndPoint, System.Net.Internals.SocketAddress)
2022-06-12 13:31:10: Exception.Data: ( )
2022-06-12 13:31:10: Exception.Source: System.Net.Sockets
2022-06-12 13:31:10: Exception.HResult: -2147467259
2022-06-12 13:31:10: Exception.StackTrace:
2022-06-12 13:31:10: at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress
2022-06-12 13:31:10: at System.Net.Sockets.Socket.Connect(EndPoint remoteEP
2022-06-12 13:31:10: at System.Net.Sockets.Socket.Connect(IPAddress address, Int32 port
2022-06-12 13:31:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port)
2022-06-12 13:31:10: --- End of stack trace from previous location where exception was thrown --
2022-06-12 13:31:10: at System.Net.Sockets.TcpClient.Connect(String hostname, Int32 port
2022-06-12 13:31:10: at System.Net.Sockets.TcpClient..ctor(String hostname, Int32 port
2022-06-12 13:31:10: at Deadline.Net.PortForwarder.b(Socket bhu)
2022-06-12 13:31:10: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022-06-12 13:31:26: Message From License Forwarder: Success: Machine registered (ip-10-1-141-99/::ffff:10.1.141.99).
2022-06-12 13:31:26: Scheduler Thread - Job's Limit Groups: engine_ubl
2022-06-12 13:31:27: 0: Loading Job's Plugin timeout is Disabled
2022-06-12 13:31:27: 0: SandboxedPlugin: Render Job As User disabled, running as current user 'deadlineuser'
2022-06-12 13:31:27: '/home/deadlineuser/Thinkbox/Deadline10/pythonAPIs/dCM9m2s++7s55Pyfom2cQ==' already exists. Skipping extraction of PythonSync.
2022-06-12 13:31:28: All job files are already synchronized
2022-06-12 13:31:28: Synchronizing Plugin Houdini from /home/deadlineuser/Thinkbox/Deadline10/cache/CYnKLgYt7a9TAQJ4j90qgAbBmRA/plugins/Houdini took: 0 seconds
2022-06-12 13:31:28: 0: Executing plugin command of type 'Initialize Plugin'
2022-06-12 13:31:29: 0: INFO: Executing plugin script '/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/plugins/62a5ea8fb96982167f3bde02/Houdini.py'
2022-06-12 13:31:29: 0: INFO: Plugin execution sandbox using Python version 3
2022-06-12 13:31:29: 0: INFO: About: Houdini Plugin for Deadline
2022-06-12 13:31:29: 0: INFO: The job's environment will be merged with the current environment before rendering
2022-06-12 13:31:29: 0: Done executing plugin command of type 'Initialize Plugin'
2022-06-12 13:31:29: 0: Start Job timeout is disabled.
2022-06-12 13:31:29: 0: Task timeout is disabled.
2022-06-12 13:31:29: 0: Loaded job: test.deadline.v021.test_pdg_ubl_h18.5_simplify.single - /obj/sphere_object1/rop_geometry_single (62a5ea8fb96982167f3bde02)
2022-06-12 13:31:29: 0: Executing plugin command of type 'Start Job'
2022-06-12 13:31:29: 0: DEBUG: S3BackedCache Client is not installed.
2022-06-12 13:31:29: 0: INFO: Executing global asset transfer preload script '/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/plugins/62a5ea8fb96982167f3bde02/GlobalAssetTransferPreLoad.py'
2022-06-12 13:31:29: 0: INFO: Looking for legacy (pre-10.0.26) AWS Portal File Transfer...
2022-06-12 13:31:29: 0: INFO: Looking for legacy (pre-10.0.26) File Transfer controller in /opt/Thinkbox/S3BackedCache/bin/task.py...
2022-06-12 13:31:29: 0: INFO: Could not find legacy (pre-10.0.26) AWS Portal File Transfer.
2022-06-12 13:31:29: 0: INFO: Legacy (pre-10.0.26) AWS Portal File Transfer is not installed on the system.
2022-06-12 13:31:29: 0: Done executing plugin command of type 'Start Job'
2022-06-12 13:31:29: 0: Plugin rendering frame(s): 1
2022-06-12 13:31:29: 0: Executing plugin command of type 'Render Task'
2022-06-12 13:31:29: 0: INFO: Set HOUDINI_PATHMAP to {"X:/":"/Volumes/cloud_prod/", "X:/":"/Volumes/cloud_prod/"}
2022-06-12 13:31:29: 0: INFO: Redshift Path Mapping...
2022-06-12 13:31:29: 0: INFO: source: "X:/" dest: "/Volumes/cloud_prod/"
2022-06-12 13:31:29: 0: INFO: source: "X:\" dest: "/Volumes/cloud_prod/"
2022-06-12 13:31:29: 0: INFO: [REDSHIFT_PATHOVERRIDE_FILE] now set to: "/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/jobsData/62a5ea8fb96982167f3bde02/RSMapping_temp3tTqs0/RSMapping.txt"
2022-06-12 13:31:29: 0: INFO: Starting Houdini Job
2022-06-12 13:31:29: 0: INFO: Stdout Redirection Enabled: True
2022-06-12 13:31:29: 0: INFO: Asynchronous Stdout Enabled: False
2022-06-12 13:31:29: 0: INFO: Stdout Handling Enabled: True
2022-06-12 13:31:29: 0: INFO: Popup Handling Enabled: True
2022-06-12 13:31:29: 0: INFO: QT Popup Handling Enabled: False
2022-06-12 13:31:29: 0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False
2022-06-12 13:31:29: 0: INFO: Using Process Tree: True
2022-06-12 13:31:29: 0: INFO: Hiding DOS Window: True
2022-06-12 13:31:29: 0: INFO: Creating New Console: False
2022-06-12 13:31:29: 0: INFO: Running as user: deadlineuser
2022-06-12 13:31:30: 0: INFO: Executable: "/opt/hfs19.0/bin/hython"
2022-06-12 13:31:30: 0: CheckPathMapping: Swapped "X:/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip" with "/Volumes/cloud_prod/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip"
2022-06-12 13:31:30: 0: INFO: Argument: "/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/plugins/62a5ea8fb96982167f3bde02/hrender_dl.py" -f 1 1 1 -g -d /obj/sphere_object1/rop_geometry_single -tempdir "/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/jobsData/62a5ea8fb96982167f3bde02/0_tempFhZSZ0" -arnoldAbortOnLicenseFail 1 "/Volumes/cloud_prod/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip"
2022-06-12 13:31:30: 0: INFO: Full Command: "/opt/hfs19.0/bin/hython" "/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/plugins/62a5ea8fb96982167f3bde02/hrender_dl.py" -f 1 1 1 -g -d /obj/sphere_object1/rop_geometry_single -tempdir "/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/jobsData/62a5ea8fb96982167f3bde02/0_tempFhZSZ0" -arnoldAbortOnLicenseFail 1 "/Volumes/cloud_prod/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip"
2022-06-12 13:31:30: 0: INFO: Startup Directory: "/opt/hfs19.0/bin"
2022-06-12 13:31:30: 0: INFO: Process Priority: BelowNormal
2022-06-12 13:31:30: 0: INFO: Process Affinity: default
2022-06-12 13:31:30: 0: INFO: Process is now running
2022-06-12 13:32:42: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'houdini' which was previously imported from '/opt/hfs19.0/houdini/pdg/types/houdini/__init__.py'. Module will be skipped.
2022-06-12 13:32:42: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'partitioners' which was previously imported from '/opt/hfs19.0/houdini/pdg/types/partitioners/__init__.py'. Module will be skipped.
2022-06-12 13:32:42: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'schedulers' which was previously imported from '/opt/hfs19.0/houdini/pdg/types/schedulers/__init__.py'. Module will be skipped.
2022-06-12 13:32:42: 0: STDOUT: PDG Type Registry: Failed to import duplicate module 'utils' which was previously imported from '/opt/hfs19.0/houdini/pdg/types/utils/__init__.py'. Module will be skipped.
2022-06-12 13:32:51: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-12 13:32:52: 0: STDOUT: Detected Houdini version: (19, 0, 622)
2022-06-12 13:32:52: 0: STDOUT: ['/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/plugins/62a5ea8fb96982167f3bde02/hrender_dl.py', '-f', '1', '1', '1', '-g', '-d', '/obj/sphere_object1/rop_geometry_single', '-tempdir', '/var/lib/Thinkbox/Deadline10/workers/ip-10-1-141-99/jobsData/62a5ea8fb96982167f3bde02/0_tempFhZSZ0', '-arnoldAbortOnLicenseFail', '1', '/Volumes/cloud_prod/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip']
2022-06-12 13:32:52: 0: STDOUT: Start: 1
2022-06-12 13:32:52: 0: STDOUT: End: 1
2022-06-12 13:32:52: 0: STDOUT: Increment: 1
2022-06-12 13:32:52: 0: STDOUT: Ignore Inputs: True
2022-06-12 13:32:52: 0: STDOUT: No output specified. Output will be handled by the driver
2022-06-12 13:32:52: 0: STDOUT: Driver: /obj/sphere_object1/rop_geometry_single
2022-06-12 13:32:52: 0: STDOUT: Input File: /Volumes/cloud_prod/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip
2022-06-12 13:32:54: 0: STDOUT: Warnings were generated during load.
2022-06-12 13:32:54: 0: STDOUT: Error loading: /Volumes/cloud_prod/temp/test.deadline.v021.test_pdg_ubl_h18.5_simplify.hip
2022-06-12 13:32:54: 0: STDOUT: Warning:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_local_workstation_test:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_on_demand_ubl:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_cloud_mantra_ubl:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_cloud_mantra_ondemand:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_on_demand_byo:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_cloud_engine_ubl:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT:
2022-06-12 13:32:54: 0: STDOUT: /obj/topnet1/deadlinescheduler_cloud_engine_byo:
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder13".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder6".
2022-06-12 13:32:54: 0: STDOUT: Skipping unrecognized parameter "folder16".
2022-06-12 13:32:54: 0: STDOUT: Begin Path Mapping
2022-06-12 13:32:55: 0: STDOUT: b''
2022-06-12 13:32:56: 0: STDOUT: b''
2022-06-12 13:32:56: 0: STDOUT: Setting variable "PDG_PATHMAP" to {"paths":[{"/Volumes/cloud_prod/":{"path":"/Volumes/cloud_prod/","zone":"LINUX"}},{"/Volumes/cloud_prod/":{"path":"/Volumes/cloud_prod/","zone":"LINUX"}}]}
2022-06-12 13:32:56: 0: STDOUT: End Path Mapping
2022-06-12 13:32:56: 0: STDOUT: ROP type: rop_geometry
2022-06-12 13:32:56: 0: STDOUT: Rendering frame 1
2022-06-12 13:32:57: 0: STDOUT: Finished Rendering
2022-06-12 13:32:59: 0: INFO: Process exit code: 0
2022-06-12 13:32:59: 0: INFO: Finished Houdini Job
2022-06-12 13:32:59: 0: Done executing plugin command of type 'Render Task'
2022-06-12 13:33:00: Port Forwarder (houdini:1715): Client connected to port forwarder.
2022-06-12 13:33:05: 0: RenderThread CancelCurrentTask called, will transition from state None to None
2022-06-12 13:33:05: 0: Executing plugin command of type 'Cancel Task'
2022-06-12 13:33:05: 0: Done executing plugin command of type 'Cancel Task'
2022-06-12 13:33:05: 0: Executing plugin command of type 'End Job'
2022-06-12 13:33:05: 0: Done executing plugin command of type 'End Job'
2022-06-12 13:33:07: Sending kill command to process deadlinesandbox.exe with id: 8840