Weird After Effects Errors during render

JTB_MPS · March 14, 2018, 8:07pm

It appears that AE is trying to relaunch itself mid-render (on a farm with only this singular After Effects job, and all tasks taken by machines, meaning machines shouldn’t be trying to grab more than one job, which we prohibit right now anyway). The log is attached below.

2018-03-14 13:47:33: 0: INFO: Attempting to create "/Users/USERNAME/Documents/ae_render_only_node.txt" to force After Effects to run in Render Engine mode 2018-03-14 13:47:33: 0: INFO: Stdout Redirection Enabled: True 2018-03-14 13:47:33: 0: INFO: Asynchronous Stdout Enabled: False 2018-03-14 13:47:33: 0: INFO: Stdout Handling Enabled: True 2018-03-14 13:47:33: 0: INFO: Popup Handling Enabled: True 2018-03-14 13:47:33: 0: INFO: QT Popup Handling Enabled: False 2018-03-14 13:47:33: 0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False 2018-03-14 13:47:33: 0: INFO: Using Process Tree: True 2018-03-14 13:47:33: 0: INFO: Hiding DOS Window: True 2018-03-14 13:47:33: 0: INFO: Creating New Console: False 2018-03-14 13:47:33: 0: INFO: Running as user: renderman 2018-03-14 13:47:33: 0: INFO: Executable: "/Applications/Adobe After Effects CC 2018/aerender" 2018-03-14 13:47:33: 0: INFO: Argument: -project "/Users/USERNAME/Library/Application Support/Thinkbox/Deadline10/slave/COMPUTERNAME/jobsData/5aa96f22e127c604f05f1fea/thread0_tempB4SQ20/FILENAME.aepx" -rqindex 1 -s 75 -e 99 -sound OFF -close DO_NOT_SAVE_CHANGES 2018-03-14 13:47:33: 0: INFO: Full Command: "/Applications/Adobe After Effects CC 2018/aerender" -project "/Users/USERNAME/Library/Application Support/Thinkbox/Deadline10/slave/COMPUTERNAME/jobsData/5aa96f22e127c604f05f1fea/thread0_tempB4SQ20/FILENAME.aepx" -rqindex 1 -s 75 -e 99 -sound OFF -close DO_NOT_SAVE_CHANGES 2018-03-14 13:47:33: 0: INFO: Startup Directory: "/Applications/Adobe After Effects CC 2018" 2018-03-14 13:47:33: 0: INFO: Process Priority: BelowNormal 2018-03-14 13:47:33: 0: INFO: Process Affinity: default 2018-03-14 13:47:33: 0: INFO: Process is now running 2018-03-14 13:48:04: 0: STDOUT: rqindex 1num 1 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: 3/14/18 1:48:04 PM MDT: Starting composition 2018_plugins_test. 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Render Settings: MPS - Full Resolution 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Quality: Best 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Resolution: Full 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Size: 3840 x 2160 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Proxy Use: Use No Proxies 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Effects: Current Settings 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Disk Cache: Read Only 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Color Depth: Current Settings 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Frame Blending: On for Checked Layers 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Field Render: Off 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Pulldown: Off 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Motion Blur: On for Checked Layers 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Solos: Current Settings 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Time Span: Custom 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Start: 00075 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: End: 00099 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Duration: 00025 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Frame Rate: 23.976 (comp) 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Guide Layers: All Off 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Skip Existing Files: Off 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Output Module: MPS - TIFF - 32bpc no alpha (linear) - TIF 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Output To: /path/to/render/location/2018_plugins_test.[####].tif 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Format: TIFF Sequence 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Output Info: - 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Start Frame: 75 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Output Audio: - 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Channels: RGB 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Depth: Floating Point 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Color: Premultiplied 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Resize: - 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Crop: - 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Final Size: 3840 x 2160 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Profile: - 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: Post-Render Action: None 2018-03-14 13:48:04: 0: STDOUT: PROGRESS: 2018-03-14 13:48:37: 0: STDOUT: PROGRESS: 00075 (1): 33 Seconds 2018-03-14 13:49:09: 0: STDOUT: PROGRESS: 00076 (2): 32 Seconds 2018-03-14 13:49:41: 0: STDOUT: PROGRESS: 00077 (3): 32 Seconds 2018-03-14 13:50:17: 0: STDOUT: PROGRESS: 00078 (4): 36 Seconds 2018-03-14 13:50:49: 0: STDOUT: PROGRESS: 00079 (5): 31 Seconds 2018-03-14 13:51:21: 0: STDOUT: PROGRESS: 00080 (6): 32 Seconds 2018-03-14 13:51:53: 0: STDOUT: PROGRESS: 00081 (7): 32 Seconds 2018-03-14 13:52:24: 0: STDOUT: PROGRESS: 00082 (8): 32 Seconds 2018-03-14 13:52:56: 0: STDOUT: PROGRESS: 00083 (9): 31 Seconds 2018-03-14 13:53:28: 0: STDOUT: PROGRESS: 00084 (10): 32 Seconds 2018-03-14 13:54:00: 0: STDOUT: PROGRESS: 00085 (11): 32 Seconds 2018-03-14 13:54:32: 0: STDOUT: PROGRESS: 00086 (12): 32 Seconds 2018-03-14 13:55:04: 0: STDOUT: PROGRESS: 00087 (13): 32 Seconds 2018-03-14 13:55:36: 0: STDOUT: PROGRESS: 00088 (14): 32 Seconds 2018-03-14 13:56:08: 0: STDOUT: PROGRESS: 00089 (15): 32 Seconds 2018-03-14 13:56:39: 0: STDOUT: PROGRESS: 00090 (16): 32 Seconds 2018-03-14 13:57:11: 0: STDOUT: PROGRESS: 00091 (17): 31 Seconds 2018-03-14 13:57:43: 0: STDOUT: PROGRESS: 00092 (18): 32 Seconds 2018-03-14 13:58:19: 0: STDOUT: PROGRESS: 00093 (19): 36 Seconds 2018-03-14 13:58:47: 0: STDOUT: aerender version 15.0.1x73 2018-03-14 13:58:47: 0: STDOUT: PROGRESS: Launching After Effects... 2018-03-14 13:58:47: 0: STDOUT: PROGRESS: ...After Effects successfully launched 2018-03-14 13:58:47: 0: INFO: Checking for file "/Users/renderman/Documents/ae_render_only_node.txt" 2018-03-14 13:58:47: 0: INFO: Attempting to delete "/Users/renderman/Documents/ae_render_only_node.txt" to allow After Effects to run in the workstation enviroment 2018-03-14 13:58:47: 0: STDOUT: aerender ERROR -609: AESend failed to send apple event at line 769 2018-03-14 13:58:48: 0: Done executing plugin command of type 'Render Task'

Not sure where to begin troubleshooting. Working with IT trying to figure it out, but so far no clues. Any ideas? We know AESend is an OSX error, not an After effects error, but it appears to try and launch AE after frame 93 and then crashes itself with the AESend error.

eamsler · March 16, 2018, 3:30pm

I’ve seen the AESend error for licensing, but it’s this guy:

aerender ERROR -1712: AESend failed to send apple event at line 769

If I were to guess, it could be that the subprocesses that are launched by AERender are crashing and the parent is trying to restart it? I don’t have an example of a healthy log at the moment, but that “Launching After Effects” should have been way higher up in the log.

MikeOwen · March 16, 2018, 6:52pm

AE isn’t trying to re-launch midway through the render. Simply, the AE StdOut is being printed out in the wrong order, after the actual render processing has taken place. Essentially the different between sync vs. async StdOut. I believe this is an AE bug, but we could run the AE render command in a shell and see how the StdOut looks then…is it in order correctly? (The times I have seen this before, display no pattern, sometimes yes, sometimes no).

For me, these obscure AE errors mean there is something wrong with the actual AE comp project file and changing/removing one thing at a time, generally narrows down what the issue is with your file. Try changing the render output image file type from tif -> tga/png and reduce the render output resolution. Make sure no mov/mp4 files are referenced in the comp and all other items in the AE render queue are deleted prior to job submission. See if any of that helps at all…

JTB_MPS · March 21, 2018, 9:56pm

Thanks, will look into all this.

eamsler · March 27, 2019, 7:06pm

Interesting discovery today. If you run the Slave under root on macOS by using sudo /Applications/Thinkbox/Deadline10/Resources/deadlineslave it seems to work fine. I’m not sure what permissions we’re running up against, but I’ll keep looking…

Update: Setting the PATH environment variable to the installation directory of AE seems to have fixed it? I’ll see if we can’t patch that in.

Update #2: We decided that messing with the path could render some plugins a bit broken, so to give control to customers I’ve written this handy tutorial on working around this issue yourself (for now)

One workaround seems to be to add the installation directory to the PATH environment variable. The expectation is that this is caused by “.” not being present in the current PATH environment as expected. We can work around this while continuing to uphold security policies by creating a script to wrap AE and set the PATH safely for us.

To do that, create a plain text file in “/Applications/Adobe After Effects CC XXXX/”, and name it “aerender_deadline”. Add the following text:

#!/bin/sh

export PATH=`dirname $0`:$PATH

aerender $@

Then make the script executable by running the following in the Terminal:

chmod +x /Applications/Adobe After Effects CC XXXX/aerender_deadline

You should be able to confirm your changes by running the executable in the same Terminal window:

/Applications/Adobe After Effects CC XXXX/aerender_deadline

If that works, we will need to change the configuration of the After Effects plugin. You’ll find this under the “Tools” menu in the Monitor as “Configure Plugins”. As an example for AE 2019, change the following:

C:\Program Files\Adobe\Adobe After Effects CC 2019\Support Files\aerender.exe
/Applications/Adobe After Effects CC 2019/aerender

To this for mac:

C:\Program Files\Adobe\Adobe After Effects CC 2019\Support Files\aerender.exe
/Applications/Adobe After Effects CC 2019/aerender_deadline

You can then copy the “aerender_deadline” file to other install folders and modify the Deadline plugin paths in the same way.