Render successful but still rendering

gabgren · December 14, 2015, 10:33pm

Hi,

Sometimes Deadline does not seem to catch that a task is done… The Slave log clearly states Render finished, but the task is still going in Deadline and therefore the slave doesn’t jump to the next task. The frame is successfully saved and not corrupted

eamsler · December 15, 2015, 3:39pm

We’re reliant on the rendering program closing to know when we can move on.

What version of Deadline is this? Also, is this a Maya job?

gabgren · December 15, 2015, 3:46pm

Hi, this is Deadline Version: 7.2.0.18 R (79a3ddcab)
And Cinema 4D R17.048

I remember seeing the same behaviour very rarely in R16,
but now in R17 this seems to be 1/10 tasks pretty much all the time

eamsler · December 15, 2015, 4:03pm

I definitely didn’t expect this to be C4D.

I wonder if it’s due to a crash. If you go over to one of the machines that’s stuck, can you see if there’s a crash dialog asking to report the issue or close the app? If that’s not the case, try closing C4D from task manager just to make sure it’s that app and not Deadline (it shouldn’t be Deadline, but worth checking).

If the app did crash, we can set the registry to make sure Windows doesn’t hold it open.

gabgren · December 15, 2015, 4:38pm

No diaglog/crash …

In the task manager tho we can clearly see that C4D is still running

I killed the process, but Deadline saw this as an error: “Renderer returned non-zero error code”

gabgren · December 15, 2015, 4:42pm

last lines from the slave log

2015-12-15 11:37:32: 0: STDOUT: Rendering Phase: Setup 2015-12-15 11:37:32: 0: STDOUT: Progress: 0% 2015-12-15 11:37:32: 0: STDOUT: 2015-12-15 11:37:32: 0: STDOUT: FRAME 24 fps:30 camMb:0 objMb:0 2015-12-15 11:37:32: 0: STDOUT: Movable:13 Nodes:64 Tri:0/7k Mesh:15 Hair:0 Used/free/total vram:100Mb/11.52Gb/12Gb 2015-12-15 11:37:33: 0: STDOUT: Progress: 3% 2015-12-15 11:37:33: 0: STDOUT: Progress: 11% 2015-12-15 11:37:34: 0: STDOUT: Progress: 20% 2015-12-15 11:37:35: 0: STDOUT: Progress: 31% 2015-12-15 11:37:35: 0: STDOUT: Progress: 43% 2015-12-15 11:37:36: 0: STDOUT: Progress: 50% 2015-12-15 11:37:36: 0: STDOUT: Progress: 65% 2015-12-15 11:37:37: 0: STDOUT: Progress: 75% 2015-12-15 11:37:38: 0: STDOUT: Progress: 86% 2015-12-15 11:37:38: 0: STDOUT: Progress: 98% 2015-12-15 11:37:38: 0: STDOUT: Progress: 100% 2015-12-15 11:37:39: 0: INFO: Task Overall Progress: 100% 2015-12-15 11:37:39: 0: STDOUT: Rendering Phase: Finalize 2015-12-15 11:37:39: 0: STDOUT: Progress: 0% 2015-12-15 11:37:39: 0: STDOUT: Progress: 2% 2015-12-15 11:37:40: 0: STDOUT: Progress: 25% 2015-12-15 11:37:40: 0: STDOUT: Progress: 63% 2015-12-15 11:37:41: 0: STDOUT: Progress: 0% 2015-12-15 11:37:41: 0: STDOUT: Progress: 2% 2015-12-15 11:37:41: 0: STDOUT: Progress: 25% 2015-12-15 11:37:42: 0: STDOUT: Progress: 63% 2015-12-15 11:37:42: 0: STDOUT: Progress: 0% 2015-12-15 11:37:42: 0: STDOUT: Progress: 2% 2015-12-15 11:37:43: 0: STDOUT: Progress: 25% 2015-12-15 11:37:44: 0: STDOUT: Progress: 63% 2015-12-15 11:37:45: 0: STDOUT: Scene created in plugin version -1 2015-12-15 11:37:45: 0: STDOUT: Progress: 100% 2015-12-15 11:37:45: 0: STDOUT: Rendering successful: 65.866 sec.

does this “Scene created in plugin version -1” line can be related ? I think it’s from Octane render. But i had the same issue with scenes rendering in standard.

gabgren · December 15, 2015, 4:45pm

Just so you know,

when i killed the Cinema4D.exe from task manager, deadline saw this as an error so it made the slave re render this task
few minutes later, same behaviour: i was stuck at 100%
i killed again c4d, and again deadline restarted this task with the same slave
it went through!

So same slave, same task. not working twice, then working!

eamsler · December 15, 2015, 5:05pm

Ugh. These are always the most fun to troubleshoot.

Forcing the application to close can cause it to return a non-zero exit code, it depends on how the software was written. At least we know Deadline can carry on after that.

I wonder if the Octane support staff have any experience with this. For fun, can you try and send a non-Octane job though and see if it gets stuck the same way? It sounds like the problem is at least reliable enough that you should see a difference.

Normally we’d try and isolate the problem away from Deadline so that the app or plugin developers of the software can have something to test with without needing Deadline… I can work with you and the OTOY staff on this one. Just CC me to your support request to them. My address is edwin@thinkboxsoftware.com.

gabgren · January 4, 2016, 2:51pm

Hi !

It just happened with standard renderer, so nothing to do with Octane.

Here is the log from the slave machine. The job is stuck at 100%

Connecting to render50win... 2016-01-04 09:48:20: 0: STDOUT: Progress: 87% 2016-01-04 09:48:20: 0: STDOUT: Progress: 88% 2016-01-04 09:48:20: 0: STDOUT: Progress: 89% 2016-01-04 09:48:20: 0: STDOUT: Progress: 90% 2016-01-04 09:48:20: 0: STDOUT: Progress: 91% 2016-01-04 09:48:20: 0: STDOUT: Progress: 92% 2016-01-04 09:48:20: 0: STDOUT: Progress: 94% 2016-01-04 09:48:20: 0: STDOUT: Progress: 95% 2016-01-04 09:48:20: 0: STDOUT: Progress: 96% 2016-01-04 09:48:20: 0: STDOUT: Progress: 97% 2016-01-04 09:48:20: 0: STDOUT: Progress: 98% 2016-01-04 09:48:20: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:20: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:20: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:20: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:20: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:20: 0: STDOUT: Rendering frame 55 at <Mon Jan 04 09:48:20 2016> 2016-01-04 09:48:20: 0: INFO: Task Overall Progress: 50% 2016-01-04 09:48:20: 0: STDOUT: Rendering Phase: Finalize 2016-01-04 09:48:20: 0: STDOUT: Progress: 0% 2016-01-04 09:48:20: 0: STDOUT: Rendering Phase: Setup 2016-01-04 09:48:20: 0: STDOUT: Progress: 0% 2016-01-04 09:48:20: 0: STDOUT: Rendering Phase: Main Render 2016-01-04 09:48:20: 0: STDOUT: Progress: 0% 2016-01-04 09:48:20: 0: STDOUT: Progress: 1% 2016-01-04 09:48:20: 0: STDOUT: Progress: 2% 2016-01-04 09:48:20: 0: STDOUT: Progress: 3% 2016-01-04 09:48:20: 0: STDOUT: Progress: 4% 2016-01-04 09:48:20: 0: STDOUT: Progress: 5% 2016-01-04 09:48:20: 0: STDOUT: Progress: 7% 2016-01-04 09:48:20: 0: STDOUT: Progress: 8% 2016-01-04 09:48:20: 0: STDOUT: Progress: 9% 2016-01-04 09:48:20: 0: STDOUT: Progress: 10% 2016-01-04 09:48:20: 0: STDOUT: Progress: 11% 2016-01-04 09:48:20: 0: STDOUT: Progress: 12% 2016-01-04 09:48:20: 0: STDOUT: Progress: 14% 2016-01-04 09:48:20: 0: STDOUT: Progress: 15% 2016-01-04 09:48:20: 0: STDOUT: Progress: 16% 2016-01-04 09:48:20: 0: STDOUT: Progress: 17% 2016-01-04 09:48:20: 0: STDOUT: Progress: 18% 2016-01-04 09:48:20: 0: STDOUT: Progress: 20% 2016-01-04 09:48:20: 0: STDOUT: Progress: 21% 2016-01-04 09:48:20: 0: STDOUT: Progress: 22% 2016-01-04 09:48:20: 0: STDOUT: Progress: 23% 2016-01-04 09:48:20: 0: STDOUT: Progress: 24% 2016-01-04 09:48:20: 0: STDOUT: Progress: 25% 2016-01-04 09:48:20: 0: STDOUT: Progress: 27% 2016-01-04 09:48:20: 0: STDOUT: Progress: 28% 2016-01-04 09:48:20: 0: STDOUT: Progress: 29% 2016-01-04 09:48:20: 0: STDOUT: Progress: 30% 2016-01-04 09:48:20: 0: STDOUT: Progress: 31% 2016-01-04 09:48:20: 0: STDOUT: Progress: 32% 2016-01-04 09:48:20: 0: STDOUT: Progress: 34% 2016-01-04 09:48:20: 0: STDOUT: Progress: 35% 2016-01-04 09:48:20: 0: STDOUT: Progress: 36% 2016-01-04 09:48:20: 0: STDOUT: Progress: 37% 2016-01-04 09:48:20: 0: STDOUT: Progress: 38% 2016-01-04 09:48:20: 0: STDOUT: Progress: 40% 2016-01-04 09:48:20: 0: STDOUT: Progress: 41% 2016-01-04 09:48:20: 0: STDOUT: Progress: 42% 2016-01-04 09:48:20: 0: STDOUT: Progress: 43% 2016-01-04 09:48:20: 0: STDOUT: Progress: 44% 2016-01-04 09:48:20: 0: STDOUT: Progress: 45% 2016-01-04 09:48:20: 0: STDOUT: Progress: 47% 2016-01-04 09:48:20: 0: STDOUT: Progress: 48% 2016-01-04 09:48:20: 0: STDOUT: Progress: 49% 2016-01-04 09:48:20: 0: STDOUT: Progress: 50% 2016-01-04 09:48:20: 0: STDOUT: Progress: 51% 2016-01-04 09:48:20: 0: STDOUT: Progress: 52% 2016-01-04 09:48:20: 0: STDOUT: Progress: 54% 2016-01-04 09:48:20: 0: STDOUT: Progress: 55% 2016-01-04 09:48:20: 0: STDOUT: Progress: 56% 2016-01-04 09:48:20: 0: STDOUT: Progress: 57% 2016-01-04 09:48:20: 0: STDOUT: Progress: 58% 2016-01-04 09:48:20: 0: STDOUT: Progress: 60% 2016-01-04 09:48:20: 0: STDOUT: Progress: 61% 2016-01-04 09:48:20: 0: STDOUT: Progress: 62% 2016-01-04 09:48:20: 0: STDOUT: Progress: 63% 2016-01-04 09:48:20: 0: STDOUT: Progress: 64% 2016-01-04 09:48:20: 0: STDOUT: Progress: 65% 2016-01-04 09:48:20: 0: STDOUT: Progress: 67% 2016-01-04 09:48:20: 0: STDOUT: Progress: 68% 2016-01-04 09:48:20: 0: STDOUT: Progress: 69% 2016-01-04 09:48:20: 0: STDOUT: Progress: 70% 2016-01-04 09:48:20: 0: STDOUT: Progress: 71% 2016-01-04 09:48:20: 0: STDOUT: Progress: 72% 2016-01-04 09:48:20: 0: STDOUT: Progress: 74% 2016-01-04 09:48:20: 0: STDOUT: Progress: 75% 2016-01-04 09:48:20: 0: STDOUT: Progress: 76% 2016-01-04 09:48:20: 0: STDOUT: Progress: 77% 2016-01-04 09:48:20: 0: STDOUT: Progress: 78% 2016-01-04 09:48:20: 0: STDOUT: Progress: 80% 2016-01-04 09:48:20: 0: STDOUT: Progress: 81% 2016-01-04 09:48:20: 0: STDOUT: Progress: 82% 2016-01-04 09:48:20: 0: STDOUT: Progress: 83% 2016-01-04 09:48:20: 0: STDOUT: Progress: 84% 2016-01-04 09:48:20: 0: STDOUT: Progress: 85% 2016-01-04 09:48:20: 0: STDOUT: Progress: 87% 2016-01-04 09:48:20: 0: STDOUT: Progress: 88% 2016-01-04 09:48:20: 0: STDOUT: Progress: 89% 2016-01-04 09:48:20: 0: STDOUT: Progress: 90% 2016-01-04 09:48:20: 0: STDOUT: Progress: 91% 2016-01-04 09:48:20: 0: STDOUT: Progress: 92% 2016-01-04 09:48:20: 0: STDOUT: Progress: 94% 2016-01-04 09:48:20: 0: STDOUT: Progress: 95% 2016-01-04 09:48:20: 0: STDOUT: Progress: 96% 2016-01-04 09:48:20: 0: STDOUT: Progress: 97% 2016-01-04 09:48:20: 0: STDOUT: Progress: 98% 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: Rendering frame 56 at <Mon Jan 04 09:48:20 2016> 2016-01-04 09:48:21: 0: INFO: Task Overall Progress: 60% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Finalize 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Setup 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Main Render 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Progress: 1% 2016-01-04 09:48:21: 0: STDOUT: Progress: 2% 2016-01-04 09:48:21: 0: STDOUT: Progress: 3% 2016-01-04 09:48:21: 0: STDOUT: Progress: 4% 2016-01-04 09:48:21: 0: STDOUT: Progress: 5% 2016-01-04 09:48:21: 0: STDOUT: Progress: 7% 2016-01-04 09:48:21: 0: STDOUT: Progress: 8% 2016-01-04 09:48:21: 0: STDOUT: Progress: 9% 2016-01-04 09:48:21: 0: STDOUT: Progress: 10% 2016-01-04 09:48:21: 0: STDOUT: Progress: 11% 2016-01-04 09:48:21: 0: STDOUT: Progress: 12% 2016-01-04 09:48:21: 0: STDOUT: Progress: 14% 2016-01-04 09:48:21: 0: STDOUT: Progress: 15% 2016-01-04 09:48:21: 0: STDOUT: Progress: 16% 2016-01-04 09:48:21: 0: STDOUT: Progress: 17% 2016-01-04 09:48:21: 0: STDOUT: Progress: 18% 2016-01-04 09:48:21: 0: STDOUT: Progress: 20% 2016-01-04 09:48:21: 0: STDOUT: Progress: 21% 2016-01-04 09:48:21: 0: STDOUT: Progress: 22% 2016-01-04 09:48:21: 0: STDOUT: Progress: 23% 2016-01-04 09:48:21: 0: STDOUT: Progress: 24% 2016-01-04 09:48:21: 0: STDOUT: Progress: 25% 2016-01-04 09:48:21: 0: STDOUT: Progress: 27% 2016-01-04 09:48:21: 0: STDOUT: Progress: 28% 2016-01-04 09:48:21: 0: STDOUT: Progress: 29% 2016-01-04 09:48:21: 0: STDOUT: Progress: 30% 2016-01-04 09:48:21: 0: STDOUT: Progress: 31% 2016-01-04 09:48:21: 0: STDOUT: Progress: 32% 2016-01-04 09:48:21: 0: STDOUT: Progress: 34% 2016-01-04 09:48:21: 0: STDOUT: Progress: 35% 2016-01-04 09:48:21: 0: STDOUT: Progress: 36% 2016-01-04 09:48:21: 0: STDOUT: Progress: 37% 2016-01-04 09:48:21: 0: STDOUT: Progress: 38% 2016-01-04 09:48:21: 0: STDOUT: Progress: 40% 2016-01-04 09:48:21: 0: STDOUT: Progress: 41% 2016-01-04 09:48:21: 0: STDOUT: Progress: 42% 2016-01-04 09:48:21: 0: STDOUT: Progress: 43% 2016-01-04 09:48:21: 0: STDOUT: Progress: 44% 2016-01-04 09:48:21: 0: STDOUT: Progress: 45% 2016-01-04 09:48:21: 0: STDOUT: Progress: 47% 2016-01-04 09:48:21: 0: STDOUT: Progress: 48% 2016-01-04 09:48:21: 0: STDOUT: Progress: 49% 2016-01-04 09:48:21: 0: STDOUT: Progress: 50% 2016-01-04 09:48:21: 0: STDOUT: Progress: 51% 2016-01-04 09:48:21: 0: STDOUT: Progress: 52% 2016-01-04 09:48:21: 0: STDOUT: Progress: 54% 2016-01-04 09:48:21: 0: STDOUT: Progress: 55% 2016-01-04 09:48:21: 0: STDOUT: Progress: 56% 2016-01-04 09:48:21: 0: STDOUT: Progress: 57% 2016-01-04 09:48:21: 0: STDOUT: Progress: 58% 2016-01-04 09:48:21: 0: STDOUT: Progress: 60% 2016-01-04 09:48:21: 0: STDOUT: Progress: 61% 2016-01-04 09:48:21: 0: STDOUT: Progress: 62% 2016-01-04 09:48:21: 0: STDOUT: Progress: 63% 2016-01-04 09:48:21: 0: STDOUT: Progress: 64% 2016-01-04 09:48:21: 0: STDOUT: Progress: 65% 2016-01-04 09:48:21: 0: STDOUT: Progress: 67% 2016-01-04 09:48:21: 0: STDOUT: Progress: 68% 2016-01-04 09:48:21: 0: STDOUT: Progress: 69% 2016-01-04 09:48:21: 0: STDOUT: Progress: 70% 2016-01-04 09:48:21: 0: STDOUT: Progress: 71% 2016-01-04 09:48:21: 0: STDOUT: Progress: 72% 2016-01-04 09:48:21: 0: STDOUT: Progress: 74% 2016-01-04 09:48:21: 0: STDOUT: Progress: 75% 2016-01-04 09:48:21: 0: STDOUT: Progress: 76% 2016-01-04 09:48:21: 0: STDOUT: Progress: 77% 2016-01-04 09:48:21: 0: STDOUT: Progress: 78% 2016-01-04 09:48:21: 0: STDOUT: Progress: 80% 2016-01-04 09:48:21: 0: STDOUT: Progress: 81% 2016-01-04 09:48:21: 0: STDOUT: Progress: 82% 2016-01-04 09:48:21: 0: STDOUT: Progress: 83% 2016-01-04 09:48:21: 0: STDOUT: Progress: 84% 2016-01-04 09:48:21: 0: STDOUT: Progress: 85% 2016-01-04 09:48:21: 0: STDOUT: Progress: 87% 2016-01-04 09:48:21: 0: STDOUT: Progress: 88% 2016-01-04 09:48:21: 0: STDOUT: Progress: 89% 2016-01-04 09:48:21: 0: STDOUT: Progress: 90% 2016-01-04 09:48:21: 0: STDOUT: Progress: 91% 2016-01-04 09:48:21: 0: STDOUT: Progress: 92% 2016-01-04 09:48:21: 0: STDOUT: Progress: 94% 2016-01-04 09:48:21: 0: STDOUT: Progress: 95% 2016-01-04 09:48:21: 0: STDOUT: Progress: 96% 2016-01-04 09:48:21: 0: STDOUT: Progress: 97% 2016-01-04 09:48:21: 0: STDOUT: Progress: 98% 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: Rendering frame 57 at <Mon Jan 04 09:48:21 2016> 2016-01-04 09:48:21: 0: INFO: Task Overall Progress: 70% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Finalize 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Setup 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Main Render 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Progress: 1% 2016-01-04 09:48:21: 0: STDOUT: Progress: 2% 2016-01-04 09:48:21: 0: STDOUT: Progress: 3% 2016-01-04 09:48:21: 0: STDOUT: Progress: 4% 2016-01-04 09:48:21: 0: STDOUT: Progress: 5% 2016-01-04 09:48:21: 0: STDOUT: Progress: 7% 2016-01-04 09:48:21: 0: STDOUT: Progress: 8% 2016-01-04 09:48:21: 0: STDOUT: Progress: 9% 2016-01-04 09:48:21: 0: STDOUT: Progress: 10% 2016-01-04 09:48:21: 0: STDOUT: Progress: 11% 2016-01-04 09:48:21: 0: STDOUT: Progress: 12% 2016-01-04 09:48:21: 0: STDOUT: Progress: 14% 2016-01-04 09:48:21: 0: STDOUT: Progress: 15% 2016-01-04 09:48:21: 0: STDOUT: Progress: 16% 2016-01-04 09:48:21: 0: STDOUT: Progress: 17% 2016-01-04 09:48:21: 0: STDOUT: Progress: 18% 2016-01-04 09:48:21: 0: STDOUT: Progress: 20% 2016-01-04 09:48:21: 0: STDOUT: Progress: 21% 2016-01-04 09:48:21: 0: STDOUT: Progress: 22% 2016-01-04 09:48:21: 0: STDOUT: Progress: 23% 2016-01-04 09:48:21: 0: STDOUT: Progress: 24% 2016-01-04 09:48:21: 0: STDOUT: Progress: 25% 2016-01-04 09:48:21: 0: STDOUT: Progress: 27% 2016-01-04 09:48:21: 0: STDOUT: Progress: 28% 2016-01-04 09:48:21: 0: STDOUT: Progress: 29% 2016-01-04 09:48:21: 0: STDOUT: Progress: 30% 2016-01-04 09:48:21: 0: STDOUT: Progress: 31% 2016-01-04 09:48:21: 0: STDOUT: Progress: 32% 2016-01-04 09:48:21: 0: STDOUT: Progress: 34% 2016-01-04 09:48:21: 0: STDOUT: Progress: 35% 2016-01-04 09:48:21: 0: STDOUT: Progress: 36% 2016-01-04 09:48:21: 0: STDOUT: Progress: 37% 2016-01-04 09:48:21: 0: STDOUT: Progress: 38% 2016-01-04 09:48:21: 0: STDOUT: Progress: 40% 2016-01-04 09:48:21: 0: STDOUT: Progress: 41% 2016-01-04 09:48:21: 0: STDOUT: Progress: 42% 2016-01-04 09:48:21: 0: STDOUT: Progress: 43% 2016-01-04 09:48:21: 0: STDOUT: Progress: 44% 2016-01-04 09:48:21: 0: STDOUT: Progress: 45% 2016-01-04 09:48:21: 0: STDOUT: Progress: 47% 2016-01-04 09:48:21: 0: STDOUT: Progress: 48% 2016-01-04 09:48:21: 0: STDOUT: Progress: 49% 2016-01-04 09:48:21: 0: STDOUT: Progress: 50% 2016-01-04 09:48:21: 0: STDOUT: Progress: 51% 2016-01-04 09:48:21: 0: STDOUT: Progress: 52% 2016-01-04 09:48:21: 0: STDOUT: Progress: 54% 2016-01-04 09:48:21: 0: STDOUT: Progress: 55% 2016-01-04 09:48:21: 0: STDOUT: Progress: 56% 2016-01-04 09:48:21: 0: STDOUT: Progress: 57% 2016-01-04 09:48:21: 0: STDOUT: Progress: 58% 2016-01-04 09:48:21: 0: STDOUT: Progress: 60% 2016-01-04 09:48:21: 0: STDOUT: Progress: 61% 2016-01-04 09:48:21: 0: STDOUT: Progress: 62% 2016-01-04 09:48:21: 0: STDOUT: Progress: 63% 2016-01-04 09:48:21: 0: STDOUT: Progress: 64% 2016-01-04 09:48:21: 0: STDOUT: Progress: 65% 2016-01-04 09:48:21: 0: STDOUT: Progress: 67% 2016-01-04 09:48:21: 0: STDOUT: Progress: 68% 2016-01-04 09:48:21: 0: STDOUT: Progress: 69% 2016-01-04 09:48:21: 0: STDOUT: Progress: 70% 2016-01-04 09:48:21: 0: STDOUT: Progress: 71% 2016-01-04 09:48:21: 0: STDOUT: Progress: 72% 2016-01-04 09:48:21: 0: STDOUT: Progress: 74% 2016-01-04 09:48:21: 0: STDOUT: Progress: 75% 2016-01-04 09:48:21: 0: STDOUT: Progress: 76% 2016-01-04 09:48:21: 0: STDOUT: Progress: 77% 2016-01-04 09:48:21: 0: STDOUT: Progress: 78% 2016-01-04 09:48:21: 0: STDOUT: Progress: 80% 2016-01-04 09:48:21: 0: STDOUT: Progress: 81% 2016-01-04 09:48:21: 0: STDOUT: Progress: 82% 2016-01-04 09:48:21: 0: STDOUT: Progress: 83% 2016-01-04 09:48:21: 0: STDOUT: Progress: 84% 2016-01-04 09:48:21: 0: STDOUT: Progress: 85% 2016-01-04 09:48:21: 0: STDOUT: Progress: 87% 2016-01-04 09:48:21: 0: STDOUT: Progress: 88% 2016-01-04 09:48:21: 0: STDOUT: Progress: 89% 2016-01-04 09:48:21: 0: STDOUT: Progress: 90% 2016-01-04 09:48:21: 0: STDOUT: Progress: 91% 2016-01-04 09:48:21: 0: STDOUT: Progress: 92% 2016-01-04 09:48:21: 0: STDOUT: Progress: 94% 2016-01-04 09:48:21: 0: STDOUT: Progress: 95% 2016-01-04 09:48:21: 0: STDOUT: Progress: 96% 2016-01-04 09:48:21: 0: STDOUT: Progress: 97% 2016-01-04 09:48:21: 0: STDOUT: Progress: 98% 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:21: 0: STDOUT: Rendering frame 58 at <Mon Jan 04 09:48:21 2016> 2016-01-04 09:48:21: 0: INFO: Task Overall Progress: 80% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Finalize 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Setup 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Rendering Phase: Main Render 2016-01-04 09:48:21: 0: STDOUT: Progress: 0% 2016-01-04 09:48:21: 0: STDOUT: Progress: 2% 2016-01-04 09:48:21: 0: STDOUT: Progress: 3% 2016-01-04 09:48:21: 0: STDOUT: Progress: 4% 2016-01-04 09:48:21: 0: STDOUT: Progress: 5% 2016-01-04 09:48:21: 0: STDOUT: Progress: 6% 2016-01-04 09:48:21: 0: STDOUT: Progress: 8% 2016-01-04 09:48:21: 0: STDOUT: Progress: 9% 2016-01-04 09:48:21: 0: STDOUT: Progress: 10% 2016-01-04 09:48:21: 0: STDOUT: Progress: 11% 2016-01-04 09:48:21: 0: STDOUT: Progress: 12% 2016-01-04 09:48:21: 0: STDOUT: Progress: 13% 2016-01-04 09:48:21: 0: STDOUT: Progress: 15% 2016-01-04 09:48:21: 0: STDOUT: Progress: 16% 2016-01-04 09:48:22: 0: STDOUT: Progress: 17% 2016-01-04 09:48:22: 0: STDOUT: Progress: 18% 2016-01-04 09:48:22: 0: STDOUT: Progress: 19% 2016-01-04 09:48:22: 0: STDOUT: Progress: 20% 2016-01-04 09:48:22: 0: STDOUT: Progress: 22% 2016-01-04 09:48:22: 0: STDOUT: Progress: 23% 2016-01-04 09:48:22: 0: STDOUT: Progress: 24% 2016-01-04 09:48:22: 0: STDOUT: Progress: 25% 2016-01-04 09:48:22: 0: STDOUT: Progress: 26% 2016-01-04 09:48:22: 0: STDOUT: Progress: 28% 2016-01-04 09:48:22: 0: STDOUT: Progress: 29% 2016-01-04 09:48:22: 0: STDOUT: Progress: 30% 2016-01-04 09:48:22: 0: STDOUT: Progress: 31% 2016-01-04 09:48:22: 0: STDOUT: Progress: 32% 2016-01-04 09:48:22: 0: STDOUT: Progress: 33% 2016-01-04 09:48:22: 0: STDOUT: Progress: 35% 2016-01-04 09:48:22: 0: STDOUT: Progress: 36% 2016-01-04 09:48:22: 0: STDOUT: Progress: 37% 2016-01-04 09:48:22: 0: STDOUT: Progress: 38% 2016-01-04 09:48:22: 0: STDOUT: Progress: 39% 2016-01-04 09:48:22: 0: STDOUT: Progress: 40% 2016-01-04 09:48:22: 0: STDOUT: Progress: 42% 2016-01-04 09:48:22: 0: STDOUT: Progress: 43% 2016-01-04 09:48:22: 0: STDOUT: Progress: 44% 2016-01-04 09:48:22: 0: STDOUT: Progress: 45% 2016-01-04 09:48:22: 0: STDOUT: Progress: 46% 2016-01-04 09:48:22: 0: STDOUT: Progress: 48% 2016-01-04 09:48:22: 0: STDOUT: Progress: 49% 2016-01-04 09:48:22: 0: STDOUT: Progress: 50% 2016-01-04 09:48:22: 0: STDOUT: Progress: 51% 2016-01-04 09:48:22: 0: STDOUT: Progress: 52% 2016-01-04 09:48:22: 0: STDOUT: Progress: 53% 2016-01-04 09:48:22: 0: STDOUT: Progress: 55% 2016-01-04 09:48:22: 0: STDOUT: Progress: 56% 2016-01-04 09:48:22: 0: STDOUT: Progress: 57% 2016-01-04 09:48:22: 0: STDOUT: Progress: 58% 2016-01-04 09:48:22: 0: STDOUT: Progress: 59% 2016-01-04 09:48:22: 0: STDOUT: Progress: 60% 2016-01-04 09:48:22: 0: STDOUT: Progress: 62% 2016-01-04 09:48:22: 0: STDOUT: Progress: 63% 2016-01-04 09:48:22: 0: STDOUT: Progress: 64% 2016-01-04 09:48:22: 0: STDOUT: Progress: 65% 2016-01-04 09:48:22: 0: STDOUT: Progress: 66% 2016-01-04 09:48:22: 0: STDOUT: Progress: 68% 2016-01-04 09:48:22: 0: STDOUT: Progress: 69% 2016-01-04 09:48:22: 0: STDOUT: Progress: 70% 2016-01-04 09:48:22: 0: STDOUT: Progress: 71% 2016-01-04 09:48:22: 0: STDOUT: Progress: 72% 2016-01-04 09:48:22: 0: STDOUT: Progress: 73% 2016-01-04 09:48:22: 0: STDOUT: Progress: 75% 2016-01-04 09:48:22: 0: STDOUT: Progress: 76% 2016-01-04 09:48:22: 0: STDOUT: Progress: 77% 2016-01-04 09:48:22: 0: STDOUT: Progress: 78% 2016-01-04 09:48:22: 0: STDOUT: Progress: 79% 2016-01-04 09:48:22: 0: STDOUT: Progress: 80% 2016-01-04 09:48:22: 0: STDOUT: Progress: 82% 2016-01-04 09:48:22: 0: STDOUT: Progress: 83% 2016-01-04 09:48:22: 0: STDOUT: Progress: 84% 2016-01-04 09:48:22: 0: STDOUT: Progress: 85% 2016-01-04 09:48:22: 0: STDOUT: Progress: 86% 2016-01-04 09:48:22: 0: STDOUT: Progress: 88% 2016-01-04 09:48:22: 0: STDOUT: Progress: 89% 2016-01-04 09:48:22: 0: STDOUT: Progress: 90% 2016-01-04 09:48:22: 0: STDOUT: Progress: 91% 2016-01-04 09:48:22: 0: STDOUT: Progress: 92% 2016-01-04 09:48:22: 0: STDOUT: Progress: 93% 2016-01-04 09:48:22: 0: STDOUT: Progress: 95% 2016-01-04 09:48:22: 0: STDOUT: Progress: 96% 2016-01-04 09:48:22: 0: STDOUT: Progress: 97% 2016-01-04 09:48:22: 0: STDOUT: Progress: 98% 2016-01-04 09:48:22: 0: STDOUT: Progress: 99% 2016-01-04 09:48:22: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:22: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:22: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:22: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:22: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)] 2016-01-04 09:48:22: 0: STDOUT: Rendering frame 59 at <Mon Jan 04 09:48:22 2016> 2016-01-04 09:48:22: 0: INFO: Task Overall Progress: 90% 2016-01-04 09:48:22: 0: STDOUT: Rendering Phase: Finalize 2016-01-04 09:48:22: 0: STDOUT: Progress: 0% 2016-01-04 09:48:22: 0: STDOUT: Rendering Phase: Setup 2016-01-04 09:48:22: 0: STDOUT: Progress: 0% 2016-01-04 09:48:22: 0: STDOUT: Rendering Phase: Main Render 2016-01-04 09:48:22: 0: STDOUT: Progress: 0% 2016-01-04 09:48:22: 0: STDOUT: Progress: 1% 2016-01-04 09:48:22: 0: STDOUT: Progress: 3% 2016-01-04 09:48:22: 0: STDOUT: Progress: 4% 2016-01-04 09:48:22: 0: STDOUT: Progress: 5% 2016-01-04 09:48:22: 0: STDOUT: Progress: 6% 2016-01-04 09:48:22: 0: STDOUT: Progress: 7% 2016-01-04 09:48:22: 0: STDOUT: Progress: 9% 2016-01-04 09:48:22: 0: STDOUT: Progress: 10% 2016-01-04 09:48:22: 0: STDOUT: Progress: 11% 2016-01-04 09:48:22: 0: STDOUT: Progress: 12% 2016-01-04 09:48:22: 0: STDOUT: Progress: 13% 2016-01-04 09:48:22: 0: STDOUT: Progress: 14% 2016-01-04 09:48:22: 0: STDOUT: Progress: 16% 2016-01-04 09:48:22: 0: STDOUT: Progress: 17% 2016-01-04 09:48:22: 0: STDOUT: Progress: 18% 2016-01-04 09:48:22: 0: STDOUT: Progress: 19% 2016-01-04 09:48:22: 0: STDOUT: Progress: 20% 2016-01-04 09:48:22: 0: STDOUT: Progress: 21% 2016-01-04 09:48:22: 0: STDOUT: Progress: 23% 2016-01-04 09:48:22: 0: STDOUT: Progress: 24% 2016-01-04 09:48:22: 0: STDOUT: Progress: 25% 2016-01-04 09:48:22: 0: STDOUT: Progress: 26% 2016-01-04 09:48:22: 0: STDOUT: Progress: 27% 2016-01-04 09:48:22: 0: STDOUT: Progress: 29% 2016-01-04 09:48:22: 0: STDOUT: Progress: 30% 2016-01-04 09:48:22: 0: STDOUT: Progress: 31% 2016-01-04 09:48:22: 0: STDOUT: Progress: 32% 2016-01-04 09:48:22: 0: STDOUT: Progress: 33% 2016-01-04 09:48:22: 0: STDOUT: Progress: 34% 2016-01-04 09:48:22: 0: STDOUT: Progress: 36% 2016-01-04 09:48:22: 0: STDOUT: Progress: 37% 2016-01-04 09:48:22: 0: STDOUT: Progress: 38% 2016-01-04 09:48:22: 0: STDOUT: Progress: 39% 2016-01-04 09:48:22: 0: STDOUT: Progress: 40% 2016-01-04 09:48:22: 0: STDOUT: Progress: 41% 2016-01-04 09:48:22: 0: STDOUT: Progress: 43% 2016-01-04 09:48:22: 0: STDOUT: Progress: 44% 2016-01-04 09:48:22: 0: STDOUT: Progress: 45% 2016-01-04 09:48:22: 0: STDOUT: Progress: 46% 2016-01-04 09:48:22: 0: STDOUT: Progress: 47% 2016-01-04 09:48:22: 0: STDOUT: Progress: 49% 2016-01-04 09:48:22: 0: STDOUT: Progress: 50% 2016-01-04 09:48:22: 0: STDOUT: Progress: 51% 2016-01-04 09:48:22: 0: STDOUT: Progress: 52% 2016-01-04 09:48:22: 0: STDOUT: Progress: 53% 2016-01-04 09:48:22: 0: STDOUT: Progress: 54% 2016-01-04 09:48:22: 0: STDOUT: Progress: 56% 2016-01-04 09:48:22: 0: STDOUT: Progress: 57% 2016-01-04 09:48:22: 0: STDOUT: Progress: 58% 2016-01-04 09:48:22: 0: STDOUT: Progress: 59% 2016-01-04 09:48:22: 0: STDOUT: Progress: 60% 2016-01-04 09:48:22: 0: STDOUT: Progress: 61% 2016-01-04 09:48:22: 0: STDOUT: Progress: 63% 2016-01-04 09:48:22: 0: STDOUT: Progress: 64% 2016-01-04 09:48:22: 0: STDOUT: Progress: 65% 2016-01-04 09:48:22: 0: STDOUT: Progress: 66% 2016-01-04 09:48:22: 0: STDOUT: Progress: 67% 2016-01-04 09:48:22: 0: STDOUT: Progress: 69% 2016-01-04 09:48:22: 0: STDOUT: Progress: 70% 2016-01-04 09:48:22: 0: STDOUT: Progress: 71% 2016-01-04 09:48:22: 0: STDOUT: Progress: 72% 2016-01-04 09:48:22: 0: STDOUT: Progress: 73% 2016-01-04 09:48:22: 0: STDOUT: Progress: 74% 2016-01-04 09:48:22: 0: STDOUT: Progress: 76% 2016-01-04 09:48:22: 0: STDOUT: Progress: 77% 2016-01-04 09:48:22: 0: STDOUT: Progress: 78% 2016-01-04 09:48:22: 0: STDOUT: Progress: 79% 2016-01-04 09:48:22: 0: STDOUT: Progress: 80% 2016-01-04 09:48:22: 0: STDOUT: Progress: 81% 2016-01-04 09:48:22: 0: STDOUT: Progress: 83% 2016-01-04 09:48:22: 0: STDOUT: Progress: 84% 2016-01-04 09:48:22: 0: STDOUT: Progress: 85% 2016-01-04 09:48:22: 0: STDOUT: Progress: 86% 2016-01-04 09:48:22: 0: STDOUT: Progress: 87% 2016-01-04 09:48:22: 0: STDOUT: Progress: 89% 2016-01-04 09:48:22: 0: STDOUT: Progress: 90% 2016-01-04 09:48:22: 0: STDOUT: Progress: 91% 2016-01-04 09:48:22: 0: STDOUT: Progress: 92% 2016-01-04 09:48:22: 0: STDOUT: Progress: 93% 2016-01-04 09:48:22: 0: STDOUT: Progress: 94% 2016-01-04 09:48:22: 0: STDOUT: Progress: 96% 2016-01-04 09:48:22: 0: STDOUT: Progress: 97% 2016-01-04 09:48:22: 0: STDOUT: Progress: 98% 2016-01-04 09:48:22: 0: STDOUT: Progress: 99% 2016-01-04 09:48:22: 0: INFO: Task Overall Progress: 100% 2016-01-04 09:48:22: 0: STDOUT: Rendering Phase: Finalize 2016-01-04 09:48:22: 0: STDOUT: Rendering successful: 4.869 sec. 2016-01-04 09:49:54: Connecting to Slave log: render50win

dwallbridge · January 4, 2016, 9:59pm

I am noticing in that log that there seem to be some critical messages at the end of each frame, but that it is still moving on. Can you verify if there is appropriate output on this job? If not, we would probably want to investigate those critical messages to see if they could be playing a part.

Example:

2016-01-04 09:48:20: 0: STDOUT: CRITICAL: Stop [atom.cpp(377)]

gabgren · January 4, 2016, 10:05pm

hi,

yeah i frankly don’t know what they are.

looking for ‘atom.cpp’, the only one i can find in the C4D install folder is under plugins/cinema4dsdk that comes with the software

gabgren · January 4, 2016, 10:11pm

and line 377 of atom.cpp is an empty line, so no clue here

dwallbridge · January 5, 2016, 7:55pm

Hello,

So it seems like there is some issue on a blank line in a file that is part of C4D. Could you check with Maxon to see if they have any idea?

gabgren · January 5, 2016, 8:04pm

Hi,
will do.

Meanwhile, can i add something to the plugin’s script? (c4d deadline plugin)

I remember back in deadline 6 I added few lines to handle missing error messages, the job was flagged as success but in fact failed.
Now it’s kind of the opposite… can i do something to tell Deadline to ignore a particular message ?

dwallbridge · January 7, 2016, 7:03pm

I just wanted to clarify that these frames are not successful, and you need to have them captured as failures, correct? The log looked like the work continued and wasn’t caught as a fail, so I wanted to make sure what you need to do with that output. Thanks.

gabgren · January 7, 2016, 7:31pm

No, the other way around.

These frames are successful !
The error messages (from C4D “atom.cpp” or Octane “plugin version -1”) may confuse us into thinking they are related…

These frames render correctly, so the error messages are just warnings that should be ignored.

It’s just that Deadline doesn’t jump to the next task and sticks at “Successful. 100% complete”

dwallbridge · January 8, 2016, 11:28pm

So I looked at the ‘end’ of your log there, and it ends with:

2016-01-04 09:48:22: 0: STDOUT: Rendering successful: 4.869 sec.

and I looked at one of ours internally and see the following:

2015-04-06 10:44:28: 0: STDOUT: Rendering successful: 161.467 sec.
2015-04-06 10:44:31: 0: INFO: Process exit code: 0
2015-04-06 10:44:31: 0: INFO: Finished Cinema 4D Task

So it looks like in your case, C4D is not exiting, or at least not telling us. Can you verify if the “CINEMA 4D.exe” process is still running when it hangs like this? If it is not, then we are not properly detecting it closing. If it is still there, then the issue is that C4D hasn’t closed, and that is what Deadline is waiting for.

Are you free for a call on Monday so we can maybe try to poke at this?

gabgren · January 8, 2016, 11:34pm

Sure thst would be great. Call me monday pm. 514-849-555

Thanks!

dwallbridge · January 11, 2016, 9:47pm

Hello Gabriel,

I just wanted to follow up on our call. I hope Maxon can give some insight into this issue as I would hate to see this continue to be an issue for you.