Hi,
We’ve been running deadline for a little while now. We are running our jobs as a dedicated deadline user on the domain. Which usually works, but sometimes a computer gets stuck on trying to access six.py from a temporary folder. (Errno 13)
We do know, that the fix for this issue is to delete the folder. But we are seeing the issue return at random, sometimes weeks later. Do we know why it creates a file it cannot access and how to prevent it from happening?
Hello @Mads_Hangaard
Thanks for reaching out. The issue happens due to permission of user account creating that folder or if there is a non empty python3.lock file instead of the folder. File lock happen if more than one user/process tries to access the folder.
I need to take a look at the verbose Worker logs to see (if anything is printed in there) why this is happening. Enable Verbose logging from Deadline Monitor> Tools> Configure Repo Options> Application Data> Check the box for Worker Verbose logs.
Now restart the Worker and reproduce the issue and then share the Worker logs from application logs folder. I know you might not be able to reproduce right away because it is random. Please share the Worker log you have already and share once more later when the issue happens. Logs — Deadline 10.2.1.0 documentation
Does this happen on all the Workers machines?
Hi, I apologize for the late reply. Here is the verbose log for how the worker is running when the issue hasn’t occurred yet. I will reply with another log, once the issue happens again.
2023-04-18 14:35:05: 0: Render Thread - Render State transition from = 'ReceivedTask' to = 'Other'
2023-04-18 14:35:05: 0: Plugin will be reloaded because a new job has been loaded.
2023-04-18 14:35:05: 0: Loading Job's Plugin timeout is Disabled
2023-04-18 14:35:05: 0: SandboxedPlugin: Render Job As User enabled, running as user 'deadline', which is defined in the User Settings for this job's user
2023-04-18 14:35:07: 0: Loaded plugin AfterEffects
2023-04-18 14:35:07: 0: Executing plugin command of type 'Initialize Plugin'
2023-04-18 14:35:07: 0: INFO: Executing plugin preload script: 'C:/Temp/Deadline10\wsx15\plugins\643e8e78207ac0545d3cbaf1\PluginPreLoad.py'
2023-04-18 14:35:07: 0: The command completed successfully.
2023-04-18 14:35:07: 0: The command completed successfully.
2023-04-18 14:35:07: 0: The command completed successfully.
2023-04-18 14:35:07: 0: The command completed successfully.
2023-04-18 14:35:07: 0: INFO: Executing plugin script 'C:/Temp/Deadline10\wsx15\plugins\643e8e78207ac0545d3cbaf1\AfterEffects.py'
2023-04-18 14:35:07: 0: INFO: Plugin execution sandbox using Python version 3
2023-04-18 14:35:07: 0: INFO: Fail Without Finished Message set to: False
2023-04-18 14:35:07: 0: INFO: Fail on Existing After Effects process: False
2023-04-18 14:35:07: 0: INFO: About: After Effects Plugin for Deadline
2023-04-18 14:35:07: 0: INFO: The job's environment will be merged with the current environment before rendering
2023-04-18 14:35:07: 0: Done executing plugin command of type 'Initialize Plugin'
2023-04-18 14:35:07: 0: Start Job timeout is disabled.
2023-04-18 14:35:07: 0: Task timeout is disabled.
2023-04-18 14:35:07: 0: Loaded job: S101_SQ030_SH010_Comp_V002 (643e8e78207ac0545d3cbaf1)
2023-04-18 14:35:07: 0: Successfully mapped P: to //dumpap3/production
2023-04-18 14:35:07: 0: Successfully mapped W: to //dumpap3/WFH
2023-04-18 14:35:08: 0: Executing plugin command of type 'Start Job'
2023-04-18 14:35:08: 0: DEBUG: S3BackedCache Client is not installed.
2023-04-18 14:35:08: 0: INFO: Executing global asset transfer preload script 'C:/Temp/Deadline10\wsx15\plugins\643e8e78207ac0545d3cbaf1\GlobalAssetTransferPreLoad.py'
2023-04-18 14:35:08: 0: INFO: Looking for legacy (pre-10.0.26) AWS Portal File Transfer...
2023-04-18 14:35:08: 0: INFO: Looking for legacy (pre-10.0.26) File Transfer controller in C:/Program Files/Thinkbox/S3BackedCache/bin/task.py...
2023-04-18 14:35:08: 0: INFO: Could not find legacy (pre-10.0.26) AWS Portal File Transfer.
2023-04-18 14:35:08: 0: INFO: Legacy (pre-10.0.26) AWS Portal File Transfer is not installed on the system.
2023-04-18 14:35:08: 0: Done executing plugin command of type 'Start Job'
2023-04-18 14:35:08: 0: Plugin rendering frame(s): 0-77
2023-04-18 14:35:08: 0: Render Thread - Render State transition from = 'Other' to = 'Rendering'
2023-04-18 14:35:08: 0: Executing plugin command of type 'Render Task'
2023-04-18 14:35:08: 0: INFO: Attempting to create "C:\Users\deadline\Documents\ae_render_only_node.txt" to force After Effects to run in Render Engine mode
2023-04-18 14:35:08: 0: INFO: Stdout Redirection Enabled: True
2023-04-18 14:35:08: 0: INFO: Stdout Handling Enabled: True
2023-04-18 14:35:08: 0: INFO: Popup Handling Enabled: True
2023-04-18 14:35:08: 0: INFO: QT Popup Handling Enabled: False
2023-04-18 14:35:08: 0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False
2023-04-18 14:35:08: 0: INFO: Using Process Tree: True
2023-04-18 14:35:08: 0: INFO: Hiding DOS Window: True
2023-04-18 14:35:08: 0: INFO: Creating New Console: False
2023-04-18 14:35:08: 0: INFO: Running as user: deadline
2023-04-18 14:35:08: 0: INFO: Executable: "C:\Program Files\Adobe\Adobe After Effects 2023\Support Files\aerender.exe"
2023-04-18 14:35:08: 0: INFO: Argument: -project "C:\Temp\Deadline10\wsx15\jobsData\643e8e78207ac0545d3cbaf1\S101_SQ030_SH010_Comp_V002.aep" -comp ".RENDER" -s 0 -e 77 -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF
2023-04-18 14:35:08: 0: INFO: Full Command: "C:\Program Files\Adobe\Adobe After Effects 2023\Support Files\aerender.exe" -project "C:\Temp\Deadline10\wsx15\jobsData\643e8e78207ac0545d3cbaf1\S101_SQ030_SH010_Comp_V002.aep" -comp ".RENDER" -s 0 -e 77 -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF
2023-04-18 14:35:08: 0: INFO: Startup Directory: "C:\Program Files\Adobe\Adobe After Effects 2023\Support Files"
2023-04-18 14:35:08: 0: INFO: Process Priority: BelowNormal
2023-04-18 14:35:08: 0: INFO: Process Affinity: default
2023-04-18 14:35:08: 0: INFO: Process is now running
2023-04-18 14:35:08: 0: INFO: Submitted from After Effects version: 23.2.1x3
2023-04-18 14:35:08: 0: STDOUT: aerender version 23.2.1x3
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Launching After Effects...
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: 18/04/2023 14.35.17: Starting composition ".RENDER".
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Render Settings: Best Settings
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Quality: Best
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Resolution: Full
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Size: 1920 x 1080
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Proxy Use: Use No Proxies
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Effects: Current Settings
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Disk Cache: Read Only
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Color Depth: Current Settings
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Frame Blending: On for Checked Layers
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Field Render: Off
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Pulldown: Off
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Motion Blur: On for Checked Layers
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Solos: Current Settings
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Time Span: Custom
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Start: 00000
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: End: 00077
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Duration: 00078
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Frame Rate: 25,00 (comp)
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Guide Layers: All Off
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Skip Existing Files: Off
2023-04-18 14:35:17: 0: STDOUT: PROGRESS:
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Output Module: Comp_Render
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Output To: P:\930462_HOJ_Project\Production\Film\S101\S101_SQ030\S101_SQ030_SH010\_CompOutput\S101_SQ030_SH010_CompOutput.mov
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Format: QuickTime
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Output Info: Apple ProRes 422 HQ
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Include: Project Link
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Output Audio: On (if comp has audio)
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Channels: RGB
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Depth: Millions of Colors
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Color: Premultiplied
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Resize: -
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Crop: -
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Final Size: 1920 x 1080
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Profile: -
2023-04-18 14:35:17: 0: STDOUT: PROGRESS: Post-Render Action: None
2023-04-18 14:35:17: 0: STDOUT: PROGRESS:
2023-04-18 14:35:38: 0: STDOUT: PROGRESS: 00000 (1): 21 Seconds
2023-04-18 14:35:38: 0: STDOUT: PROGRESS: 00001 (2): 0 Seconds
2023-04-18 14:35:38: 0: STDOUT: PROGRESS: 00002 (3): 0 Seconds
2023-04-18 14:35:38: 0: STDOUT: PROGRESS: 00003 (4): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00004 (5): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00005 (6): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00006 (7): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00007 (8): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00008 (9): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00009 (10): 0 Seconds
2023-04-18 14:35:39: 0: STDOUT: PROGRESS: 00010 (11): 1 Seconds
2023-04-18 14:35:40: 0: STDOUT: PROGRESS: 00011 (12): 0 Seconds
2023-04-18 14:35:40: 0: STDOUT: PROGRESS: 00012 (13): 1 Seconds
2023-04-18 14:35:40: 0: STDOUT: PROGRESS: 00013 (14): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00014 (15): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00015 (16): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00016 (17): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00017 (18): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00018 (19): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00019 (20): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00020 (21): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00021 (22): 0 Seconds
2023-04-18 14:35:41: 0: STDOUT: PROGRESS: 00022 (23): 1 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00023 (24): 0 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00024 (25): 0 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00025 (26): 0 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00026 (27): 0 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00027 (28): 0 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00028 (29): 1 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00029 (30): 0 Seconds
2023-04-18 14:35:42: 0: STDOUT: PROGRESS: 00030 (31): 0 Seconds
2023-04-18 14:35:43: 0: STDOUT: PROGRESS: 00031 (32): 0 Seconds
2023-04-18 14:35:43: 0: STDOUT: PROGRESS: 00032 (33): 1 Seconds
2023-04-18 14:35:43: 0: STDOUT: PROGRESS: 00033 (34): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00034 (35): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00035 (36): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00036 (37): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00037 (38): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00038 (39): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00039 (40): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00040 (41): 0 Seconds
2023-04-18 14:35:44: 0: STDOUT: PROGRESS: 00041 (42): 1 Seconds
2023-04-18 14:35:45: 0: STDOUT: PROGRESS: 00042 (43): 0 Seconds
2023-04-18 14:35:45: 0: STDOUT: PROGRESS: 00043 (44): 0 Seconds
2023-04-18 14:35:45: 0: STDOUT: PROGRESS: 00044 (45): 1 Seconds
2023-04-18 14:35:45: 0: STDOUT: PROGRESS: 00045 (46): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00046 (47): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00047 (48): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00048 (49): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00049 (50): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00050 (51): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00051 (52): 0 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00052 (53): 1 Seconds
2023-04-18 14:35:46: 0: STDOUT: PROGRESS: 00053 (54): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00054 (55): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00055 (56): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00056 (57): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00057 (58): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00058 (59): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00059 (60): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00060 (61): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00061 (62): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00062 (63): 1 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00063 (64): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00064 (65): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00065 (66): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00066 (67): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00067 (68): 0 Seconds
2023-04-18 14:35:47: 0: STDOUT: PROGRESS: 00068 (69): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00069 (70): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00070 (71): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00071 (72): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00072 (73): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00073 (74): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00074 (75): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00075 (76): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00076 (77): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 00077 (78): 0 Seconds
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: 18/04/2023 14.35.48: Finished composition ".RENDER".
2023-04-18 14:35:48: 0: STDOUT: PROGRESS: Total Time Elapsed: 31 Seconds
2023-04-18 14:35:48: 0: INFO: Process exit code: 0
2023-04-18 14:35:48: 0: INFO: Checking for file "C:\Users\deadline\Documents\ae_render_only_node.txt"
2023-04-18 14:35:48: 0: INFO: Attempting to delete "C:\Users\deadline\Documents\ae_render_only_node.txt" to allow After Effects to run in the workstation environment
2023-04-18 14:35:48: 0: CheckPathMapping: Swapped "\\p\930462_HOJ_Project\Production\Film\S101\S101_SQ030\S101_SQ030_SH010\_CompOutput\S101_SQ030_SH010_CompOutput.mov" with "\\dumpap3\production\930462_HOJ_Project\Production\Film\S101\S101_SQ030\S101_SQ030_SH010\_CompOutput\S101_SQ030_SH010_CompOutput.mov"
2023-04-18 14:35:48: 0: INFO: Checking file size of "\\dumpap3\production\930462_HOJ_Project\Production\Film\S101\S101_SQ030\S101_SQ030_SH010\_CompOutput\S101_SQ030_SH010_CompOutput.mov"
2023-04-18 14:35:48: 0: Done executing plugin command of type 'Render Task'
2023-04-18 14:35:48: 0: Render time for frame(s): 40.939 s
2023-04-18 14:35:48: 0: Total time for task: 43.862 s
Here is the log from a different machine, that suddenly went into the permission denied loop. It seems to be able to happen to any given worker machine. But I have definitely observed that it happens more often on certain machines, like this one for example.
=======================================================
Error
=======================================================
PermissionError : [Errno 13] Permission denied: 'C:\\Users\\deadline\\AppData\\Local\\Thinkbox\\Deadline10\\pythonAPIs\\LzpSIezHU5KgVLKWHPqCQg==\\six.py'
=======================================================
Type
=======================================================
RenderPluginException
=======================================================
Stack Trace
=======================================================
at Deadline.Plugins.SandboxedPlugin.d(DeadlineMessage bgo, CancellationToken bgp)
at Deadline.Plugins.SandboxedPlugin.Initialize(Job job, CancellationToken cancellationToken)
at Deadline.Slaves.SlaveRenderThread.e(String ajv, Job ajw, CancellationToken ajx)
at Deadline.Slaves.SlaveRenderThread.b(TaskLogWriter ajr, CancellationToken ajs)
=======================================================
Log
=======================================================
2023-04-21 12:24:09: 0: Render Thread - Render State transition from = 'ReceivedTask' to = 'Other'
2023-04-21 12:24:09: 0: Loading Job's Plugin timeout is Disabled
2023-04-21 12:24:09: 0: SandboxedPlugin: Render Job As User enabled, running as user 'deadline', which is defined in the User Settings for this job's user
2023-04-21 12:24:11: 0: Loaded plugin AfterEffects
2023-04-21 12:24:11: 0: Executing plugin command of type 'Initialize Plugin'
2023-04-21 12:24:11: 0: INFO: Executing plugin preload script: 'C:/Temp/Deadline10\wsx21\plugins\6442643f207ac0545d3cdd6d\PluginPreLoad.py'
2023-04-21 12:24:11: 0: The command completed successfully.
2023-04-21 12:24:11: 0: The command completed successfully.
2023-04-21 12:24:11: 0: The command completed successfully.
2023-04-21 12:24:11: 0: The command completed successfully.
2023-04-21 12:24:11: 0: INFO: Executing plugin script 'C:/Temp/Deadline10\wsx21\plugins\6442643f207ac0545d3cdd6d\AfterEffects.py'
2023-04-21 12:24:11: 0: Encountered an error while executing plugin command of type 'Initialize Plugin'
=======================================================
Details
=======================================================
Date: 04/21/2023 12:24:14
Frames: 0-77
Elapsed Time: 00:00:00:05
Job Submit Date: 04/21/2023 12:23:59
Job User: jc
Average RAM Usage: 0 (0%)
Peak RAM Usage: 0 (0%)
Average CPU Usage: 0%
Peak CPU Usage: 0%
Used CPU Clocks (x10^6 cycles): 0
Total CPU Clocks (x10^6 cycles): 0
=======================================================
Worker Information
=======================================================
Worker Name: WSX21
Version: v10.2.0.10 Release (3b87216c7)
Operating System: Windows 10 Pro
Running As Service: Yes
Machine User: deadline
IP Address: 192.168.0.183
MAC Address: 2C:F0:5D:9D:E5:88
CPU Architecture: x64
CPUs: 16
CPU Usage: 7%
Memory Usage: 20.3 GB / 31.9 GB (63%)
Free Disk Space: 103.814 GB
Video Card: NVIDIA GeForce RTX 3060
Here is a log of the machine working, before it starts failing.
=======================================================
Log
=======================================================
2023-04-20 16:20:57: 0: Render Thread - Render State transition from = 'ReceivedTask' to = 'Other'
2023-04-20 16:20:57: 0: Plugin will be reloaded because a new job has been loaded.
2023-04-20 16:20:57: 0: Loading Job's Plugin timeout is Disabled
2023-04-20 16:20:57: 0: SandboxedPlugin: Render Job As User enabled, running as user 'deadline', which is defined in the User Settings for this job's user
2023-04-20 16:20:59: 0: Loaded plugin AfterEffects
2023-04-20 16:21:00: 0: Executing plugin command of type 'Initialize Plugin'
2023-04-20 16:21:00: 0: INFO: Executing plugin preload script: 'C:/Temp/Deadline10\wsx21\plugins\64414a48207ac0545d3cd472\PluginPreLoad.py'
2023-04-20 16:21:00: 0: The command completed successfully.
2023-04-20 16:21:00: 0: The command completed successfully.
2023-04-20 16:21:00: 0: The command completed successfully.
2023-04-20 16:21:00: 0: The command completed successfully.
2023-04-20 16:21:00: 0: INFO: Executing plugin script 'C:/Temp/Deadline10\wsx21\plugins\64414a48207ac0545d3cd472\AfterEffects.py'
2023-04-20 16:21:00: 0: INFO: Plugin execution sandbox using Python version 3
2023-04-20 16:21:00: 0: INFO: Fail Without Finished Message set to: False
2023-04-20 16:21:00: 0: INFO: Fail on Existing After Effects process: False
2023-04-20 16:21:00: 0: INFO: About: After Effects Plugin for Deadline
2023-04-20 16:21:00: 0: INFO: The job's environment will be merged with the current environment before rendering
2023-04-20 16:21:00: 0: Done executing plugin command of type 'Initialize Plugin'
2023-04-20 16:21:00: 0: Start Job timeout is disabled.
2023-04-20 16:21:00: 0: Task timeout is disabled.
2023-04-20 16:21:00: 0: Loaded job: S107_SQ090_SH050_Comp_V002 (64414a48207ac0545d3cd472)
2023-04-20 16:21:00: 0: Successfully mapped P: to //dumpap3/production
2023-04-20 16:21:00: 0: Successfully mapped W: to //dumpap3/WFH
2023-04-20 16:21:00: 0: Executing plugin command of type 'Start Job'
2023-04-20 16:21:00: 0: DEBUG: S3BackedCache Client is not installed.
2023-04-20 16:21:00: 0: INFO: Executing global asset transfer preload script 'C:/Temp/Deadline10\wsx21\plugins\64414a48207ac0545d3cd472\GlobalAssetTransferPreLoad.py'
2023-04-20 16:21:00: 0: INFO: Looking for legacy (pre-10.0.26) AWS Portal File Transfer...
2023-04-20 16:21:00: 0: INFO: Looking for legacy (pre-10.0.26) File Transfer controller in C:/Program Files/Thinkbox/S3BackedCache/bin/task.py...
2023-04-20 16:21:00: 0: INFO: Could not find legacy (pre-10.0.26) AWS Portal File Transfer.
2023-04-20 16:21:00: 0: INFO: Legacy (pre-10.0.26) AWS Portal File Transfer is not installed on the system.
2023-04-20 16:21:00: 0: Done executing plugin command of type 'Start Job'
2023-04-20 16:21:00: 0: Plugin rendering frame(s): 0-39
2023-04-20 16:21:00: 0: Render Thread - Render State transition from = 'Other' to = 'Rendering'
2023-04-20 16:21:01: 0: Executing plugin command of type 'Render Task'
2023-04-20 16:21:01: 0: INFO: Attempting to create "C:\Users\deadline\Documents\ae_render_only_node.txt" to force After Effects to run in Render Engine mode
2023-04-20 16:21:01: 0: INFO: Stdout Redirection Enabled: True
2023-04-20 16:21:01: 0: INFO: Stdout Handling Enabled: True
2023-04-20 16:21:01: 0: INFO: Popup Handling Enabled: True
2023-04-20 16:21:01: 0: INFO: QT Popup Handling Enabled: False
2023-04-20 16:21:01: 0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False
2023-04-20 16:21:01: 0: INFO: Using Process Tree: True
2023-04-20 16:21:01: 0: INFO: Hiding DOS Window: True
2023-04-20 16:21:01: 0: INFO: Creating New Console: False
2023-04-20 16:21:01: 0: INFO: Running as user: deadline
2023-04-20 16:21:01: 0: INFO: Executable: "C:\Program Files\Adobe\Adobe After Effects 2023\Support Files\aerender.exe"
2023-04-20 16:21:01: 0: INFO: Argument: -project "C:\Temp\Deadline10\wsx21\jobsData\64414a48207ac0545d3cd472\S107_SQ090_SH050_Comp_V002.aep" -comp ".RENDER" -s 0 -e 39 -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF
2023-04-20 16:21:01: 0: INFO: Full Command: "C:\Program Files\Adobe\Adobe After Effects 2023\Support Files\aerender.exe" -project "C:\Temp\Deadline10\wsx21\jobsData\64414a48207ac0545d3cd472\S107_SQ090_SH050_Comp_V002.aep" -comp ".RENDER" -s 0 -e 39 -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF
2023-04-20 16:21:01: 0: INFO: Startup Directory: "C:\Program Files\Adobe\Adobe After Effects 2023\Support Files"
2023-04-20 16:21:01: 0: INFO: Process Priority: BelowNormal
2023-04-20 16:21:01: 0: INFO: Process Affinity: default
2023-04-20 16:21:01: 0: INFO: Process is now running
2023-04-20 16:21:01: 0: INFO: Submitted from After Effects version: 23.2.1x3
2023-04-20 16:21:01: 0: STDOUT: aerender version 23.2.1x3
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Launching After Effects...
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: 20/04/2023 16.21.17: Starting composition ".RENDER".
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Render Settings: Best Settings
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Quality: Best
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Resolution: Full
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Size: 1920 x 1080
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Proxy Use: Use No Proxies
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Effects: Current Settings
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Disk Cache: Read Only
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Color Depth: Current Settings
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Frame Blending: On for Checked Layers
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Field Render: Off
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Pulldown: Off
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Motion Blur: On for Checked Layers
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Solos: Current Settings
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Time Span: Custom
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Start: 00000
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: End: 00039
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Duration: 00040
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Frame Rate: 25,00 (comp)
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Guide Layers: All Off
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Skip Existing Files: Off
2023-04-20 16:21:17: 0: STDOUT: PROGRESS:
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Output Module: Comp_Render
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Output To: P:\930462_HOJ_Project\Production\Film\S107\S107_SQ090\S107_SQ090_SH050\_CompOutput\S107_SQ090_SH050_CompOutput.mov
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Format: QuickTime
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Output Info: Apple ProRes 4444
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Include: Project Link
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Output Audio: On (if comp has audio)
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Channels: RGB + Alpha
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Depth: Trillions of Colors+
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Color: Premultiplied
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Resize: -
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Crop: -
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Final Size: 1920 x 1080
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Profile: -
2023-04-20 16:21:17: 0: STDOUT: PROGRESS: Post-Render Action: None
2023-04-20 16:21:17: 0: STDOUT: PROGRESS:
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00000 (1): 26 Seconds
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00001 (2): 1 Seconds
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00002 (3): 0 Seconds
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00003 (4): 0 Seconds
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00004 (5): 0 Seconds
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00005 (6): 0 Seconds
2023-04-20 16:21:44: 0: STDOUT: PROGRESS: 00006 (7): 0 Seconds
2023-04-20 16:21:48: 0: STDOUT: PROGRESS: 00007 (8): 3 Seconds
2023-04-20 16:21:50: 0: STDOUT: PROGRESS: 00008 (9): 2 Seconds
2023-04-20 16:21:51: 0: STDOUT: PROGRESS: 00009 (10): 1 Seconds
2023-04-20 16:21:52: 0: STDOUT: PROGRESS: 00010 (11): 1 Seconds
2023-04-20 16:21:53: 0: STDOUT: PROGRESS: 00011 (12): 2 Seconds
2023-04-20 16:21:53: 0: STDOUT: PROGRESS: 00012 (13): 0 Seconds
2023-04-20 16:21:54: 0: STDOUT: PROGRESS: 00013 (14): 0 Seconds
2023-04-20 16:21:54: 0: STDOUT: PROGRESS: 00014 (15): 0 Seconds
2023-04-20 16:21:56: 0: STDOUT: PROGRESS: 00015 (16): 2 Seconds
2023-04-20 16:21:57: 0: STDOUT: PROGRESS: 00016 (17): 1 Seconds
2023-04-20 16:21:58: 0: STDOUT: PROGRESS: 00017 (18): 1 Seconds
2023-04-20 16:21:59: 0: STDOUT: PROGRESS: 00018 (19): 2 Seconds
2023-04-20 16:21:59: 0: STDOUT: PROGRESS: 00019 (20): 0 Seconds
2023-04-20 16:21:59: 0: STDOUT: PROGRESS: 00020 (21): 0 Seconds
2023-04-20 16:22:00: 0: STDOUT: PROGRESS: 00021 (22): 1 Seconds
2023-04-20 16:22:00: 0: STDOUT: PROGRESS: 00022 (23): 0 Seconds
2023-04-20 16:22:02: 0: STDOUT: PROGRESS: 00023 (24): 2 Seconds
2023-04-20 16:22:05: 0: STDOUT: PROGRESS: 00024 (25): 2 Seconds
2023-04-20 16:22:05: 0: STDOUT: PROGRESS: 00025 (26): 1 Seconds
2023-04-20 16:22:07: 0: STDOUT: PROGRESS: 00026 (27): 1 Seconds
2023-04-20 16:22:07: 0: STDOUT: PROGRESS: 00027 (28): 1 Seconds
2023-04-20 16:22:08: 0: STDOUT: PROGRESS: 00028 (29): 0 Seconds
2023-04-20 16:22:09: 0: STDOUT: PROGRESS: 00029 (30): 1 Seconds
2023-04-20 16:22:10: 0: STDOUT: PROGRESS: 00030 (31): 2 Seconds
2023-04-20 16:22:12: 0: STDOUT: PROGRESS: 00031 (32): 1 Seconds
2023-04-20 16:22:13: 0: STDOUT: PROGRESS: 00032 (33): 1 Seconds
2023-04-20 16:22:14: 0: STDOUT: PROGRESS: 00033 (34): 1 Seconds
2023-04-20 16:22:21: 0: STDOUT: PROGRESS: 00034 (35): 7 Seconds
2023-04-20 16:22:21: 0: STDOUT: PROGRESS: 00035 (36): 1 Seconds
2023-04-20 16:22:21: 0: STDOUT: PROGRESS: 00036 (37): 0 Seconds
2023-04-20 16:22:22: 0: STDOUT: PROGRESS: 00037 (38): 0 Seconds
2023-04-20 16:22:23: 0: STDOUT: PROGRESS: 00038 (39): 1 Seconds
2023-04-20 16:22:23: 0: STDOUT: PROGRESS: 00039 (40): 0 Seconds
2023-04-20 16:22:24: 0: STDOUT: PROGRESS: 20/04/2023 16.22.23: Finished composition ".RENDER".
2023-04-20 16:22:24: 0: STDOUT: PROGRESS: Total Time Elapsed: 1 Min, 6 Sec
2023-04-20 16:22:24: 0: INFO: Process exit code: 0
2023-04-20 16:22:24: 0: INFO: Checking for file "C:\Users\deadline\Documents\ae_render_only_node.txt"
2023-04-20 16:22:24: 0: INFO: Attempting to delete "C:\Users\deadline\Documents\ae_render_only_node.txt" to allow After Effects to run in the workstation environment
2023-04-20 16:22:24: 0: CheckPathMapping: Swapped "\\p\930462_HOJ_Project\Production\Film\S107\S107_SQ090\S107_SQ090_SH050\_CompOutput\S107_SQ090_SH050_CompOutput.mov" with "\\dumpap3\production\930462_HOJ_Project\Production\Film\S107\S107_SQ090\S107_SQ090_SH050\_CompOutput\S107_SQ090_SH050_CompOutput.mov"
2023-04-20 16:22:24: 0: INFO: Checking file size of "\\dumpap3\production\930462_HOJ_Project\Production\Film\S107\S107_SQ090\S107_SQ090_SH050\_CompOutput\S107_SQ090_SH050_CompOutput.mov"
2023-04-20 16:22:24: 0: Done executing plugin command of type 'Render Task'
2023-04-20 16:22:24: 0: Render time for frame(s): 1.393 m
2023-04-20 16:22:24: 0: Total time for task: 1.466 m
2023-04-20 16:22:25: 0: Saving task log...
=======================================================
Details
=======================================================
Date: 04/20/2023 16:22:25
Frames: 0-39
Job Submit Date: 04/20/2023 16:20:55
Job User: slc
Average RAM Usage: 5021474304 (15%)
Peak RAM Usage: 16639324160 (49%)
Average CPU Usage: 15%
Peak CPU Usage: 77%
Used CPU Clocks (x10^6 cycles): 547098
Total CPU Clocks (x10^6 cycles): 3647318
=======================================================
Worker Information
=======================================================
Worker Name: WSX21
Version: v10.2.0.10 Release (3b87216c7)
Operating System: Windows 10 Pro
Running As Service: Yes
Machine User: deadline
IP Address: 192.168.0.183
MAC Address: 2C:F0:5D:9D:E5:88
CPU Architecture: x64
CPUs: 16
CPU Usage: 51%
Memory Usage: 30.8 GB / 31.9 GB (96%)
Free Disk Space: 96.898 GB
Video Card: NVIDIA GeForce RTX 3060
And here is an overview of the logs, from the moment where it starts failing.
Hi @zainali,
Is there any other information I can provide?
To me, it seems like the issue is provoked by the computer being restarted. But I believe it doesn’t happen every time a machine is restarted.
Hello @Mads_Hangaard
I could see your machine user is same as user rendering the Job, you can disable Render Job as user as there are identified Issues using that feature on windows .
To check the calls made to pythonAPIs folder, you can Install Process Monitoring Tool on render node , monitor the activity by reproducing the issue, we would be able to get some data when the permissions error is recreated. If possible, can you please capture and share logs.
Hey @Nreddy
Thanks for your answer, we’re kind of dependent on “Render Job as user” as different users have access to different projects etc. We use a general render user, to ensure consistency in permissions.
I can try and setup Process Monitoring on a few machines, that seem prone to getting the error. But it’d seem the error happens after a reboot. How’d we go about capturing that with Process Monitor? Do you know if we can automatically start capturing after a reboot?
Hello @Mads_Hangaard
I am not sure, I don’t think so it is possible to add capture filters in to script, but process Monitor doesn’t do anything with the files, it tracks all the calls made to the files. So, In your case If you can reproduce the Issue by restarting the machine and run the process Monitor by filtering path to PythonAPIs folder, that Information might be helpful.
Hey, just want to say I haven’t forgotten about this thread. I am planning to do more testing on this issue, we’re just currently quite busy to get ready for Annecy, and it’s not a crucial issue atm. But eventually we’ll get back to this.
As I have resigned from my current position, I might not be around to finally find a solution to this issue. But I’ll just tag the person which will take over. @Copenhagen_Bombay
Hello!
The permission issue you are running into is with python cache deadline pulls while rendering. With Render as a User enabled, we have seen issue with Windows nodes that it fails on reading the files written by the other user. It runs into permission issue when one user tries to access the file written by a different user.
The workaround we suggest on this is to delete the cache folder and Deadline would pull the files and create a new cache for python files.
Hi Karpreet
Thank you for getting back to us. I’m will be following up on this thread from now on.
Our current workaround is, as you suggest, to delete the folders more or less manually. But its both time consuming to do for each render-node and happens too inconsistently for us to check for it all the time.
Do you have any suggestions to making this part of a pre-load script that deadline could run itself? Or a function/script we could add to the deadline worker?
We do also run into that we have to stop/kill the worker to be allowed to delete the folder. I assume that the python.lock file is the culprit here, and some process doesn’t let it go.
I would love to have a reboot and recache button or script I could run 
The fear is, that with being stuck doing it manually, its very possible to forget to check if the render-nodes are working properly, and suddenly you have lost a lot of render time because a couple of nodes haven’t been doing anything.
I have a processMonitor log of the pythonAPI when the issue occured. I can filter by ACCESS DENIED and see the pythonAPI/…/six.py file being the issue.
Is there anywhere I can upload it because I can’t attach it directly here.
You can send a ticket in to support@awsthinkbox.zendesk.com with the files. Just mention the forum thread so it’s clear what they’re in reference to.
