Thinkbox Deadline Rendering Broken in v24.1.0

[Nigrini Studio]

The latest version of After Effects seems to have broken the ability for deadline workers to launch AE. All workers immediately return with this error:

Error: FailRenderException : After Effects returned non-zero error code: 132. Check the render log.

if you take the "full command" and paste it into a terminal window, it launches just fine. For example (from the deadline worker log)

2024-01-17 18:05:38: 0: INFO: Full Command: "/Applications/Adobe After Effects 2024/aerender" -project "/Users/Shared/Thinkbox/Deadline10/workers/EDIT1/jobsData/65a7fd08da4823eb325531ff/DEADLINE__TEMP.aep" -comp "Comp 1" -s 0 -e 0 -output "/Volumes/EDIT_Local/_TEMP RENDER/Comp 1_[#####].png" -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF

This is fine. But the job launched from deadline immediately fails with exit code 132. This only occurs with AE version 24.1.0. All previous versions of AE 2024 and AE 2023 are fine.

My question is what is exit code 132, and what would make it fail when launched from Deadline, but not from a regular command line render in terminal. (using the current user or sudo makes no differnence, all is fine from terminal). 

Again, this is a new bug that showed up with AE 24.1.0 so it is not a problem with the operating system or a major AE update, or a deadline update. Reverting to AE 24.0.3 fixes the problem. This is also true of all the machines in our render farm, so it's not just one node. Anyone have any thoughts?

-Robert

[JohnColombo]

Hi @Nigrini Studio,

Thank you for reporting this issue. Are you able to collect an application log from the aerender instance so we can get more information? The application log can be enabled by placing an empty "AERender Log.txt" file in "~/Library/Preferences/Adobe/After Effects/24.1/logs". After attempting to run the job via Deadline, check the "AERender Log.txt" to see a verbose application log. Please DM me a link to this .txt file, as it contains file paths that might contain sensitive information.

Since the command works when run directly but not when run via Deadline, it is possible that Deadline does not have sufficient permissions to launch AE. Have you reached out to Deadline for more info? I will ask internally about exit code 132, but it appears that the code could be any number of things.

Thanks again for reporting this issue and for any further information you can provide, 

- John, After Effects Engineering Team 

[Nigrini Studio]

Hey John,

Added that log file (and double checked the spelling/path) but the log remains empty. The aerender process exits before it even starts the "launching after effects" part. It does populate the log if i paste the "full command" into deadline and it renders ok. But from deadline, aerender seems to reject the command entirely and just exits with code 132. FYI this is using the latest version of deadline (both repository and client) that i got from the AWS thinkbox downloads yesterday - v 10.3.1.4

2024-01-18 11:54:04: 0: INFO: Running as user: edit5

2024-01-18 11:54:04: 0: INFO: Executable: "/Applications/Adobe After Effects 2024/aerender"

2024-01-18 11:54:04: 0: INFO: Rendering to network drive

2024-01-18 11:54:04: 0: INFO: Validating the path: '/Users/Shared/TEMP_RENDER'

2024-01-18 11:54:04: 0: INFO: Argument: -project "/Users/Shared/Thinkbox/Deadline10/workers/EDIT5/jobsData/65a9566cf002dcbfece85fe6/TEST.aep" -comp "TestComp" -s 0 -e 0 -output "/Users/Shared/TEMP_RENDER/TestComp_[#####].png" -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF

2024-01-18 11:54:04: 0: INFO: Full Command: "/Applications/Adobe After Effects 2024/aerender" -project "/Users/Shared/Thinkbox/Deadline10/workers/EDIT5/jobsData/65a9566cf002dcbfece85fe6/TEST.aep" -comp "TestComp" -s 0 -e 0 -output "/Users/Shared/TEMP_RENDER/TestComp_[#####].png" -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF

2024-01-18 11:54:04: 0: INFO: Startup Directory: "/Applications/Adobe After Effects 2024"

2024-01-18 11:54:04: 0: INFO: Process Priority: BelowNormal

2024-01-18 11:54:04: 0: INFO: Process Affinity: default

2024-01-18 11:54:04: 0: INFO: Process is now running

2024-01-18 11:54:04: 0: INFO: Process exit code: 132

Then the error line:

Error: After Effects returned non-zero error code: 132. Check the render log.

is what is returned from the "CheckExitCode" method from the AfterEffects.py plugin which checks the return code from aerender.

-Robert

[JohnColombo]

Thank you for that additional info, @Nigrini Studio. The early failure might indicate the failure is occurring upstream from aerender, but would you be able to check the macOS Console to see if there is any additional information on the aerender process being run by Deadline?

Thanks again,

- John, After Effects Engineering Team 

[Nigrini Studio]

So this is interesting. Every time it tries to start the job, aerender is actually crashing and generating a crash report. Here is an example:

{"app_name":"aerender","timestamp":"2024-01-18 12:52:15.00 -0500","app_version":"","slice_uuid":"403c7051-69ac-3d17-b229-17a9516ab530","build_version":"","platform":1,"share_with_app_devs":0,"is_first_party":1,"bug_type":"309","os_version":"macOS 14.2.1 (23C71)","roots_installed":0,"incident_id":"BA893F37-D050-4901-9CE7-930B9C698E9F","name":"aerender"}
{
"uptime" : 2100,
"procRole" : "Unspecified",
"version" : 2,
"userID" : 501,
"deployVersion" : 210,
"modelCode" : "Mac13,2",
"coalitionID" : 2635,
"osVersion" : {
"train" : "macOS 14.2.1",
"build" : "23C71",
"releaseType" : "User"
},
"captureTime" : "2024-01-18 12:52:15.5070 -0500",
"codeSigningMonitor" : 1,
"incident" : "BA893F37-D050-4901-9CE7-930B9C698E9F",
"pid" : 2566,
"translated" : true,
"cpuType" : "X86-64",
"roots_installed" : 0,
"bug_type" : "309",
"procLaunch" : "2024-01-18 12:52:15.4682 -0500",
"procStartAbsTime" : 50548095408,
"procExitAbsTime" : 50549016439,
"procName" : "aerender",
"procPath" : "\/Applications\/Adobe After Effects 2024\/aerender",
"parentProc" : "deadlinesandbox.exe",
"parentPid" : 2551,
"coalitionName" : "com.thinkboxsoftware.DeadlineWorker",
"crashReporterKey" : "3E68560D-9E6B-A628-2927-C5FD9202114B",
"responsiblePid" : 2482,
"responsibleProc" : "deadlineworker.exe",
"codeSigningID" : "aerender",
"codeSigningTeamID" : "JQ525L2MZD",
"codeSigningFlags" : 570491653,
"codeSigningValidationCategory" : 6,
"codeSigningTrustLevel" : 4294967295,
"sip" : "enabled",
"exception" : {"codes":"0x0000000000000001, 0x0000000000000000","rawCodes":[1,0],"type":"EXC_BAD_INSTRUCTION","signal":"SIGILL"},
"termination" : {"flags":0,"code":4,"namespace":"SIGNAL","indicator":"Illegal instruction: 4","byProc":"exc handler","byPid":2566},
"extMods" : {"caller":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"system":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"targeted":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"warnings":0},
"faultingThread" : 0,
"threads" : [{"triggered":true,"id":38420,"threadState":{"flavor":"x86_THREAD_STATE","rbp":{"value":13051737632},"r12":{"value":105553123792800},"rosetta":{"tmp2":{"value":70585347968376868},"tmp1":{"value":9547624362789566917},"tmp0":{"value":4342965613}},"rbx":{"value":4},"r8":{"value":79},"r15":{"value":17},"r10":{"value":0},"rdx":{"value":0},"rdi":{"value":30},"r9":{"value":13051738955},"r13":{"value":4294967295},"rflags":{"value":519},"rax":{"value":4},"rsp":{"value":13051737344},"r11":{"value":13051738982},"rcx":{"value":0},"r14":{"value":4342987194},"rsi":{"value":1}},"queue":"com.apple.main-thread","frames":[{"imageOffset":9581,"symbol":"main","symbolLocation":957,"imageIndex":3},{"imageOffset":25478,"symbol":"start","symbolLocation":1942,"imageIndex":0}]},{"id":38423,"name":"com.apple.rosetta.exceptionserver","threadState":{"flavor":"x86_THREAD_STATE","rbp":{"value":34097745362944},"r12":{"value":140705868933420},"rosetta":{"tmp2":{"value":0},"tmp1":{"value":4496830765059},"tmp0":{"value":10337986281472}},"rbx":{"value":4496830765059},"r8":{"value":7939},"r15":{"value":4362080256,"region":"<translation info unavailable>"},"r10":{"value":15586436317184},"rdx":{"value":0},"rdi":{"value":0},"r9":{"value":0},"r13":{"value":4477844352},"rflags":{"value":582},"rax":{"value":268451845},"rsp":{"value":10337986281472},"r11":{"value":0},"rcx":{"value":17314086914},"r14":{"value":4343125544},"rsi":{"value":2616}},"frames":[{"imageOffset":17044,"imageIndex":1}]}],
"usedImages" : [
{
"source" : "P",
"arch" : "x86_64",
"base" : 8640593920,
"size" : 655360,
"uuid" : "ab17bf63-259b-3b48-8d70-863166a2191c",
"path" : "\/usr\/lib\/dyld",
"name" : "dyld"
},
{
"source" : "P",
"arch" : "arm64",
"base" : 140703125041152,
"size" : 196608,
"uuid" : "c4c97159-5c72-3e75-ba2d-d6ca98ea626f",
"path" : "\/usr\/libexec\/rosetta\/runtime",
"name" : "runtime"
},
{
"source" : "P",
"arch" : "arm64",
"base" : 4477427712,
"size" : 344064,
"uuid" : "7af8ba1e-5c4d-393d-99cd-92566f60c450",
"path" : "\/Library\/Apple\/*\/libRosettaRuntime",
"name" : "libRosettaRuntime"
},
{
"source" : "P",
"arch" : "x86_64",
"base" : 4342956032,
"size" : 32768,
"uuid" : "403c7051-69ac-3d17-b229-17a9516ab530",
"path" : "\/Applications\/Adobe After Effects 2024\/aerender",
"name" : "aerender"
},
{
"size" : 0,
"source" : "A",
"base" : 0,
"uuid" : "00000000-0000-0000-0000-000000000000"
}
],
"sharedCache" : {
"base" : 140703437832192,
"size" : 21474836480,
"uuid" : "aa32606f-3f8a-36dc-89ab-9c1bd7bf3104"
},
"vmSummary" : "ReadOnly portion of Libraries: Total=431.7M resident=0K(0%) swapped_out_or_unallocated=431.7M(100%)\nWritable regions: Total=682.6M written=0K(0%) resident=0K(0%) swapped_out=0K(0%) unallocated=682.6M(100%)\n\n VIRTUAL REGION \nREGION TYPE SIZE COUNT (non-coalesced) \n=========== ======= ======= \nActivity Tracing 256K 1 \nKernel Alloc Once 8K 1 \nMALLOC 522.2M 12 \nMALLOC guard page 96K 6 \nRosetta Arena 4096K 2 \nRosetta Generic 832K 205 \nRosetta IndirectBranch 32K 1 \nRosetta JIT 128.0M 1 \nRosetta Return Stack 20K 2 \nRosetta Thread Context 20K 2 \nStack 8176K 1 \nStack Guard 56.0M 1 \nVM_ALLOCATE 14.7M 8 \n__DATA 16.4M 308 \n__DATA_CONST 14.8M 198 \n__DATA_DIRTY 650K 103 \n__FONT_DATA 2352 1 \n__LINKEDIT 178.7M 9 \n__OBJC_RO 71.1M 1 \n__OBJC_RW 2166K 2 \n__TEXT 253.0M 327 \ndyld private memory 260K 2 \nmapped file 7.3G 471 \nshared memory 32K 2 \nunshared pmap 4368K 3 \n=========== ======= ======= \nTOTAL 8.5G 1670 \n",
"legacyInfo" : {
"threadTriggered" : {
"queue" : "com.apple.main-thread"
}
},
"logWritingSignature" : "2acec04a5d6698054ee8870352d455468d2d8417",
"trialInfo" : {
"rollouts" : [
{
"rolloutId" : "6410af69ed1e1e7ab93ed169",
"factorPackIds" : {

},
"deploymentId" : 240000010
},
{
"rolloutId" : "632e3f9c01482c74ed76392d",
"factorPackIds" : {
"SIRI_TEXT_TO_SPEECH" : "658231c5ce88fb026191cad6"
},
"deploymentId" : 240000356
}
],
"experiments" : [

]
},
"reportNotes" : [
"PC register does not match crashing frame (0x0 vs 0x102DC656D)"
]
}

[JohnColombo]

Thank you for that crash log, @Nigrini Studio! I'll show this to some more of our engineers and see what we can glean from it. It appears that Rosetta might be involved; are you intentionally running Deadline or AE under Rosetta?

Cheers,

- John, After Effects Engineering Team 

[Nigrini Studio]

Thanks for looking into all this! As far as i'm aware, deadline is all built on the .NET Core runtime for x86 on mac to be able to develop cross-platform. So everything deadline related runs in rosetta, and does not have m1 native binaries at all (i believe this is the case, but wouldn't bet my life on it). AE is not set to run in rosetta (i think this option was even removed in AE2024). 24.0.3 was also not run using rosetta, but did launch fine from deadline. Thanks again!

-Robert

[Nigrini Studio]

Another potential clue. For unrelated reasons, i was seeing if i could force AE 2024 to open in rosetta despite the "open using Rosetta" checkbox being gone in 2024. If i run the binary directly in the app bundle using:

arch -x86_64 "/path/to/AE/binary" 

it does succesfully launch in rosetta (and thus, i can use my x86 plugins) when using AE 24.0.3. However when trying the same command on the binary in AE 24.1.0, it bails with the following error:

illegal hardware instruction arch -x86_64.

In case that info is helpful.

-Robert

[JohnColombo]

That's a good clue, @Nigrini Studio. This seems to strongly indicate running under Rosetta as the root issue. Support for running After Effects and all other Adobe video apps under Rosetta was removed in version 24.0 (e.g. the "Open using Rosetta" checkbox no longer appears in the Get Info dialog for After Effects 24.0 and later). It may still have been possible to run the executable 24.0.3 with "arch -x86_64 ...", but changes incompatible with Rosetta may have been introduced into 24.1 since Rosetta is no longer supported.

This may need to be handled on the Deadline side by having Deadline run AE natively on Apple silicon devices, rather than under Rosetta.

[nishu_kush]

Hope the suggestion above helped.
Feel free to reach out. Moving this thread from Bugs to Discussions for now.

Thanks,
Nishu