From: Victor DiMichina <victor@(email surpressed)>
Subject: aerender batch framing
   Date: Mon, 14 Mar 2011 16:56:45 -0400

Anyone have the issue with batching aerender where ae returns an exitcode of 0 "success" yet only renders a portion of the batch?    I've attached two log files,  one is 

"aerender_full_success.rtf"  showing a log from a successful 10-frame batch,  highligting the batch frames,  and the output.   So the node was asked to render frames 211-220, and it rendered them all,  exiting with a success code.

"aerender_partial_false_success.rtf"  shows a log from an attempted 10-frame batch (same job),   and shows the output being only one frame.    Sometimes it's one,  sometimes it will do three,  five,  it's all random.   


AE has many weirdnesses that I have to deal with,   but usually I can parse for errors and auto-requeue the frame.   This one shows no difference that I can see in the log,  it just doesn't render the frames.

Anyone seen this?    I want to report this to Adobe.     I also want to find a pattern here to check for this and re-queue frames.

{\rtf1\ansi\ansicpg1252\cocoartf1038\cocoasubrtf350
{\fonttbl\f0\fswiss\fcharset0 Helvetica;}
{\colortbl;\red255\green255\blue255;\red5\green0\blue255;}
\margl1440\margr1440\vieww28860\viewh10780\viewkind0
\pard\tx720\tx1440\tx2160\tx2880\tx3600\tx4320\tx5040\tx5760\tx6480\tx7200\tx7920\tx8640\ql\qnatural\pardirnatural

\f0\fs24 \cf0 Done     0211       1       mp-grima         31469    mp-aragorn.10  03/14,12:22:33 00:04:31     \
###\
### mp-aragorn.10: 0211\
###\
--------------- Rush 102.42a9d --------------\
--       Host: mp-grima\
--        Pid: 31469\
--      Title: AE_10-r01_sn1200_DISP_001.aep\
--      Jobid: mp-aragorn.10\
--      Frame: 0211\
--      Tries: 0\
--      Owner: joeblow (-/-)\
--  RunningAs: cineon (1110/20)\
--   Priority: 452\
--       Nice: 10\
--     Tmpdir: /var/tmp/.RUSH_TMP.1350\
--    LogFile: /bandaid/RushLogs/r01_sn1200_DISP_001.aep.log/0211\
--    Command: perl /bandaid/2D_Apps/RushSubmits/submit-afterfx.pl -render CS5  /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep r01_sn1200_DISP_001 - 10 280 3 Fail 0 off -mp\
--    Started: Mon Mar 14 12:22:33 2011\
--------------------------------------------\
\
	  SCENEPATH:  /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep\
	       COMP: r01_sn1200_DISP_001\
	  OUTPUTDIR: -\
	  AEVERSION: CS5\
	RENDERFLAGS: -mp\
	BATCHFRAMES: 10 (211-220)\
	    RETRIES: 3 (Fail after 3 retries)\
	       PATH: /Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/usr/local/rush/bin:/usr/local/rush/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/rush/bin\
\
Executing: aerender -project " /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep" -comp "r01_sn1200_DISP_001"  -s 211 -e 220 -mp\
WARNING:After Effects warning: Output color depth exceeds project color depth.\
PROGRESS:  3/14/11 12:22:46 PM PDT: Starting composition r01_sn1200_DISP_001.\
\
\
PROGRESS:  Render Settings: Best Settings\
PROGRESS:  Quality: Best\
PROGRESS:  Resolution: Full\
PROGRESS:  Size: 2048 x 1234\
PROGRESS:  Proxy Use: Use No Proxies\
PROGRESS:  Effects: Current Settings\
PROGRESS:  Disk Cache: Read Only\
PROGRESS:  Color Depth: Current Settings\
PROGRESS:  Frame Blending: On for Checked Layers\
PROGRESS:  Field Render: Off\
PROGRESS:  Pulldown: Off\
PROGRESS:  Motion Blur: On for Checked Layers\
PROGRESS:  Use OpenGL: Off\
PROGRESS:  Solos: Current Settings\
PROGRESS:  Time Span: Custom\

\b PROGRESS:  Start: 00211\
PROGRESS:  End: 00220\
PROGRESS:  Duration: 00010\

\b0 PROGRESS:  Frame Rate: 24.00 (comp)\
PROGRESS:  Guide Layers: All Off\
PROGRESS:  Skip Existing Files: Off\
PROGRESS:  \
PROGRESS:  Output Module: EXR_4_Displacement\
PROGRESS:  Output To:  /foo/bar/path/to/r01_sn1200/elements/2D_elements/r01_sn1200_DISP_001/r01_sn1200_DISP_001_[#####].exr\
PROGRESS:  Format: OpenEXR\
PROGRESS:  Output Info: Piz compression\
PROGRESS:  Start Frame: 211\
PROGRESS:  Output Audio: -\
PROGRESS:  Channels: RGB\
PROGRESS:  Depth: Floating Point\
PROGRESS:  Color: Premultiplied\
PROGRESS:  Resize: -\
PROGRESS:  Crop: -\
PROGRESS:  Final Size: 2048 x 1234\
PROGRESS:  Profile:  -\
PROGRESS:  Embed Profile:  \
PROGRESS:   \
PROGRESS:  Post-Render Action: None\
PROGRESS:   \
PROGRESS:   \
PROGRESS:   \
PROGRESS:  \

\b \cf2 PROGRESS:  00211 (1): 29 Seconds\
PROGRESS:  00212 (2): 30 Seconds\
PROGRESS:  00213 (3): 29 Seconds\
PROGRESS:  00214 (4): 26 Seconds\
PROGRESS:  00215 (5): 25 Seconds\
PROGRESS:  00216 (6): 24 Seconds\
PROGRESS:  00217 (7): 25 Seconds\
PROGRESS:  00218 (8): 22 Seconds\
PROGRESS:  00219 (9): 22 Seconds\
PROGRESS:  00220 (10): 21 Seconds\

\b0 \cf0 PROGRESS:  3/14/11 12:27:00 PM PDT: Finished composition r01_sn1200_DISP_001.\
\
\
\
PROGRESS:  Total Time Elapsed: 4 Min, 14 Sec\
aerender version 10.0.1x19\
PROGRESS: Launching After Effects...\
PROGRESS: ...After Effects successfully launched\
\
--- AERENDER SUCCEEDS}

{\rtf1\ansi\ansicpg1252\cocoartf1038\cocoasubrtf350
{\fonttbl\f0\fswiss\fcharset0 Helvetica;}
{\colortbl;\red255\green255\blue255;\red255\green17\blue17;}
\margl1440\margr1440\vieww27560\viewh14680\viewkind0
\pard\tx720\tx1440\tx2160\tx2880\tx3600\tx4320\tx5040\tx5760\tx6480\tx7200\tx7920\tx8640\ql\qnatural\pardirnatural

\f0\fs24 \cf0 Done     0191       1       mp-theoden       23042    mp-aragorn.10  03/14,12:20:23 00:03:39     \
###\
### mp-aragorn.10: 0191\
###\
--------------- Rush 102.42a9d --------------\
--       Host: mp-theoden\
--        Pid: 23042\
--      Title: AE_10-r01_sn1200_DISP_001.aep\
--      Jobid: mp-aragorn.10\
--      Frame: 0191\
--      Tries: 0\
--      Owner: joeblow (-/-)\
--  RunningAs: cineon (1110/20)\
--   Priority: 452\
--       Nice: 10\
--     Tmpdir: /var/tmp/.RUSH_TMP.1533\
--    LogFile: /bandaid/RushLogs/r01_sn1200_DISP_001.aep.log/0191\
--    Command: perl /bandaid/2D_Apps/RushSubmits/submit-afterfx.pl -render CS5   /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep r01_sn1200_DISP_001 - 10 280 3 Fail 0 off -mp\
--    Started: Mon Mar 14 12:20:23 2011\
--------------------------------------------\
\
	  SCENEPATH:  /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep\
	       COMP: r01_sn1200_DISP_001\
	  OUTPUTDIR: -\
	  AEVERSION: CS5\
	RENDERFLAGS: -mp\
	BATCHFRAMES: 10 (191-200)\
	    RETRIES: 3 (Fail after 3 retries)\
	       PATH: /Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/Applications/Adobe After Effects CS5:/usr/local/rush/bin:/usr/local/rush/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/rush/bin\
\
Executing: aerender -project " /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep" -comp "r01_sn1200_DISP_001"  -s 191 -e 200 -mp\
WARNING:After Effects warning: Output color depth exceeds project color depth.\
PROGRESS:  3/14/11 12:20:32 PM PDT: Starting composition r01_sn1200_DISP_001.\
\
\
PROGRESS:  Render Settings: Best Settings\
PROGRESS:  Quality: Best\
PROGRESS:  Resolution: Full\
PROGRESS:  Size: 2048 x 1234\
PROGRESS:  Proxy Use: Use No Proxies\
PROGRESS:  Effects: Current Settings\
PROGRESS:  Disk Cache: Read Only\
PROGRESS:  Color Depth: Current Settings\
PROGRESS:  Frame Blending: On for Checked Layers\
PROGRESS:  Field Render: Off\
PROGRESS:  Pulldown: Off\
PROGRESS:  Motion Blur: On for Checked Layers\
PROGRESS:  Use OpenGL: Off\
PROGRESS:  Solos: Current Settings\
PROGRESS:  Time Span: Custom\

\b PROGRESS:  Start: 00191\
PROGRESS:  End: 00200\
PROGRESS:  Duration: 00010\

\b0 PROGRESS:  Frame Rate: 24.00 (comp)\
PROGRESS:  Guide Layers: All Off\
PROGRESS:  Skip Existing Files: Off\
PROGRESS:  \
PROGRESS:  Output Module: EXR_4_Displacement\
PROGRESS:  Output To: /foo/bar/path/to/r01_sn1200/elements/2D_elements/r01_sn1200_DISP_001/r01_sn1200_DISP_001_[#####].exr\
PROGRESS:  Format: OpenEXR\
PROGRESS:  Output Info: Piz compression\
PROGRESS:  Start Frame: 191\
PROGRESS:  Output Audio: -\
PROGRESS:  Channels: RGB\
PROGRESS:  Depth: Floating Point\
PROGRESS:  Color: Premultiplied\
PROGRESS:  Resize: -\
PROGRESS:  Crop: -\
PROGRESS:  Final Size: 2048 x 1234\
PROGRESS:  Profile:  -\
PROGRESS:  Embed Profile:  \
PROGRESS:   \
PROGRESS:  Post-Render Action: None\
PROGRESS:   \
PROGRESS:   \
PROGRESS:   \
PROGRESS:  \

\b \cf2 PROGRESS:  00191 (1): 3 Min, 25 Sec\

\b0 \cf0 PROGRESS:  3/14/11 12:23:58 PM PDT: Finished composition r01_sn1200_DISP_001.\
\
\
\
PROGRESS:  Total Time Elapsed: 3 Min, 26 Sec\
aerender version 10.0.1x19\
PROGRESS: Launching After Effects...\
PROGRESS: ...After Effects successfully launched\
\
--- AERENDER SUCCEEDS\
}

Cheers.

Vic

Victor DiMichina wrote:
> Anyone have the issue with batching aerender where ae returns an exitcode of 0 "success" yet only renders a portion of the batch?    I've attached two log files,  one is 
> 
> "aerender_full_success.rtf"  showing a log from a successful 10-frame batch,  highligting the batch frames,  and the output.   So the node was asked to render frames 211-220, and it rendered them all,  exiting with a success code.
> 
> "aerender_partial_false_success.rtf"  shows a log from an attempted 10-frame batch (same job),   and shows the output being only one frame.    Sometimes it's one,  sometimes it will do three,  five,  it's all random.   
> 
> 
> AE has many weirdnesses that I have to deal with,   but usually I can parse for errors and auto-requeue the frame.   This one shows no difference that I can see in the log,  it just doesn't render the frames.
> 
> Anyone seen this?    I want to report this to Adobe.     I also want to find a pattern here to check for this and re-queue frames.

	Is it the case where when you requeue the batch, it works fine the next time,
	even on the same machine?

	You should report it, as AE is probably not reporting errors correctly here.

	To see what's actually happening, check your client and file server's
	system logs (eg. /var/log/system.log, /var/log/secure.log, /var/log/samba*)
	to see if the network file system is generating spurious permission errors
	or some such.

	I've seen a few cases where e.g. the /var/log/system.log of mac file servers
	reported random kerberos that resulted in 'permission denied' situations
	only with AE + NFS, and AE + samba. It seemed like a two part problem;
	1) AE was exacerbating an OS problem to occur (fault of the OS), and
	2) AE wasn't reporting the OS error in the logs (fault of AE).

	You should report it to Adobe I think.
	I've seen other customers run into this, and it's mostly been recently
	(last few months). Not sure if it's something to do with a recent upgrade
	of OSX, or AE, or some magic combo.

	BTW, is your file server MacOS? I've seen a pattern of this where the
	server was a recent release of OSX (Snow Leopard/10.6).

-- 
Greg Ercolano, erco@(email surpressed)
Seriss Corporation
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)ext.23
Fax: (Tel# suppressed)
Cel: (Tel# suppressed)

On Mar 14, 2011, at 3:31 PM, Greg Ercolano wrote:

> [posted to rush.general]
> 
> Victor DiMichina wrote:
>> Anyone have the issue with batching aerender where ae returns an exitcode of 0 "success" yet only renders a portion of the batch?    I've attached two log files,  one is 
>> 
>> "aerender_full_success.rtf"  showing a log from a successful 10-frame batch,  highligting the batch frames,  and the output.   So the node was asked to render frames 211-220, and it rendered them all,  exiting with a success code.
>> 
>> "aerender_partial_false_success.rtf"  shows a log from an attempted 10-frame batch (same job),   and shows the output being only one frame.    Sometimes it's one,  sometimes it will do three,  five,  it's all random.   
>> 
>> 
>> AE has many weirdnesses that I have to deal with,   but usually I can parse for errors and auto-requeue the frame.   This one shows no difference that I can see in the log,  it just doesn't render the frames.
>> 
>> Anyone seen this?    I want to report this to Adobe.     I also want to find a pattern here to check for this and re-queue frames.
> 
> 	Is it the case where when you requeue the batch, it works fine the next time,
> 	even on the same machine?
> 
> 	You should report it, as AE is probably not reporting errors correctly here.
> 
> 	To see what's actually happening, check your client and file server's
> 	system logs (eg. /var/log/system.log, /var/log/secure.log, /var/log/samba*)
> 	to see if the network file system is generating spurious permission errors
> 	or some such.
> 
> 	I've seen a few cases where e.g. the /var/log/system.log of mac file servers
> 	reported random kerberos that resulted in 'permission denied' situations
> 	only with AE + NFS, and AE + samba. It seemed like a two part problem;
> 	1) AE was exacerbating an OS problem to occur (fault of the OS), and
> 	2) AE wasn't reporting the OS error in the logs (fault of AE).
> 
> 	You should report it to Adobe I think.

I will report it to Adobe.    Not sure how confident I am that they'll care,  but it's worth a try.
We're OS X server with AFP share.    it's been doing this before 10.6,  but I recently started batch framing,  so I don't know if previous versions of OS X server/client/AE had this problem.  

> 	I've seen other customers run into this, and it's mostly been recently
> 	(last few months). Not sure if it's something to do with a recent upgrade
> 	of OSX, or AE, or some magic combo.

It's been pre-10.6 for me,  At least since 10.3

Cheers,
Vic

> 
> 	BTW, is your file server MacOS? I've seen a pattern of this where the
> 	server was a recent release of OSX (Snow Leopard/10.6).
> 
> -- 
> Greg Ercolano, erco@(email surpressed)
> Seriss Corporation
> Rush Render Queue, http://seriss.com/rush/
> Tel: +1 626-576-0010 ext.23
> Fax: +1 626-576-0020
> Cel: +1 310-266-8906

Victor DiMichina wrote:
>> 	You should report it to Adobe I think.
> 
> I will report it to Adobe.    Not sure how confident I am that they'll
> care,  but it's worth a try.
> We're OS X server with AFP share.    it's been doing this before 10.6,
> but I recently started batch framing,  so I don't know if previous
> versions of OS X server/client/AE had this problem.

	The log should raise some eyebrows.
	With a successful run you get:

Executing: aerender -project " /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep" -comp "r01_sn1200_DISP_001"  -s 211 -e 220 -mp
[..]
PROGRESS:  00211 (1): 29 Seconds
PROGRESS:  00212 (2): 30 Seconds
PROGRESS:  00213 (3): 29 Seconds
PROGRESS:  00214 (4): 26 Seconds
PROGRESS:  00215 (5): 25 Seconds
PROGRESS:  00216 (6): 24 Seconds
PROGRESS:  00217 (7): 25 Seconds
PROGRESS:  00218 (8): 22 Seconds
PROGRESS:  00219 (9): 22 Seconds
PROGRESS:  00220 (10): 21 Seconds

PROGRESS:  3/14/11 12:27:00 PM PDT: Finished composition 'r01_sn1200_DISP_001'.

	..and with a bad run you get:

Executing: aerender -project " /foo/bar/path/to/r01_sn1200/projects/ae/r01_sn1200_DISP_001.aep" -comp "r01_sn1200_DISP_001"  -s 191 -e 200 -mp
[..]
PROGRESS:  00191 (1): 3 Min, 25 Sec

PROGRESS:  3/14/11 12:23:58 PM PDT: Finished composition 'r01_sn1200_DISP_001'

	In the latter case, from the developer's point of view, the /lack/ of information
	between the first frame rendered (191) and the 'Finished composition'
	should be disturbing to them; it should at least show errors if errors occurred
	one way or the other about 191 thru 200; it should not just say 'nothing'.

	In the above error case, the exit code of 0 is bad too; if all frames didn't
	render, it should not return a zero (success) exit code.

	There should be more careful attention towards error conditions in AE;
	that's always been a problem. It seems like some image formats are better
	advertised than others.

	Also, it's important they log actual OS errors instead of just programmer's
	interpretations of what went wrong. In the times I see AE throw permission errors,
	it prints non-OS errors suggesting a problem with write permissions, but it should
	really include the actual OS errors (using strerror() and errno) so that we can see
	'Permission denied' or 'No such file or directory', and under windows it should use
	the equivalent [FormatMessage() & GetLastError()] so we can see things like
	'Logon failure: unknown user name or bad password.' or 'The network path was not found.'


	Feel free to include my observations and email address

>> 	I've seen other customers run into this, and it's mostly been recently
>> 	(last few months). Not sure if it's something to do with a recent upgrade
>> 	of OSX, or AE, or some magic combo.
> 
> It's been pre-10.6 for me,  At least since 10.3

        10.3, wow, that'd be 'forever' then.


-- 
Greg Ercolano, erco@(email surpressed)
Seriss Corporation
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)ext.23
Fax: (Tel# suppressed)
Cel: (Tel# suppressed)