I'm recieving a Zencoder postback notification failure in Zencoders Notifications History: 'Status: failed'

The response received is 'No response was received because the notification timed out'. However, the Drupal log conflicts with this and says 'Zencoder: Postback received from the Zencoder Transcoding servers for fid: 2894, Zencoder job id: 2310358'. Which is same job id Zencoder says failed.

A look in files directory shows that the file was indeed transfered back from Zencoder, and the encoding was completed without error.

Looking in the DB. 'video_queue' for the vid/fid in question still has a status of '5' which suggest that the file is still processing and no postback was received. But 'file_managed' has been updated with to reflect the URI of the *converted* file already - which agrees with the postback notice in the log, but the 'filesize' in 'file_managed' has been written as '0' even thought the file is in fact complete and intact. So something is awry.

To make matters worse - this is only happening with certain files. My initial thought was that it's something to do with the the 'video queue time out setting' in the video module Cron settings - which I've now set to over an hour (3600secs). But the files in question are being returned with 10-15 mins...... which doesn't add up.

It's more looking like there is something unusual happening in the postback handler....

Any ideas on how to solve?

Thanks

Comments

Tsubo’s picture

Tsubo commented

More material re #1. I include a copy of the 'notification sent' from Zencoder, as I'm guessing the issue might be manifesting as a result of the specific contents.

{"output":{"video_bitrate_in_kbps":804,"audio_codec":"aac","duration_in_ms":609087,"frame_rate":25.0,"md5_checksum":null,"channels":"2","state":"finished","audio_bitrate_in_kbps":61,"file_size_in_bytes":66153484,"width":620,"format":"mpeg4","url":"https://zencoder-live.s3.amazonaws.com/o/20120725/6a4186b073737b59c84a888e9ee9f8e5/seabreeze_view-h.264_lan_mp4_1343232493.mp4?AWSAccessKeyId=AKIAI456JQ76GBU7FECA&Signature=nb7Q%2BTbhcOa6fQsMw2ED7ueaLJE%3D&Expires=1343320524","video_codec":"h264","height":348,"label":"video-2894","total_bitrate_in_kbps":865,"audio_sample_rate":48000,"id":43097635},"input":{"video_bitrate_in_kbps":1399,"audio_codec":"aac","duration_in_ms":609040,"frame_rate":25.0,"md5_checksum":null,"channels":"2","state":"finished","audio_bitrate_in_kbps":109,"file_size_in_bytes":115247638,"width":854,"format":"mpeg4","video_codec":"h264","height":480,"total_bitrate_in_kbps":1508,"audio_sample_rate":48000,"id":23098087},"job":{"created_at":"2012-07-25T16:08:13Z","test":false,"updated_at":"2012-07-25T16:35:24Z","pass_through":null,"submitted_at":"2012-07-25T16:08:13Z","state":"finished","id":23103583}}

Jorrit’s picture

Jorrit commented
Status: Active » Postponed (maintainer needs more info)

Are there any entries in the Apache error log? The reason may be that the postback request times out during execution. The log message is written immediately at the beginning of the code.

Tsubo’s picture

Tsubo commented

Not seeing anything in the error log at all.
The raw log has:

50.23.89.168 - - [25/Jul/2012:12:44:17 -0500] "POST /postback/jobs HTTP/1.1" 200 - "-" "Zencoder Notifier/2.0"

which time matches with the notice I'm getting in the Drupal log:

Type:	transcoder
Date:	Wednesday, 25 July, 2012 - 18:44
User: 	Anonymous
Location:	http://mydomain.com/postback/jobs
Referrer	
Message:	Zencoder: Postback received from the Zencoder Transcoding servers for fid: 2894, Zencoder job id: 23103583.
Severity:	notice
Hostname:	50.23.89.168
Tsubo’s picture

Tsubo commented

More info:

Zencoder obviously keeps re-sending the postback notifications (upto 25 times) periodically. An each one is received and logged by Drupal. Just nothing happening to the status in 'video_queue' - stays on '5'..... and then the erroneous insertion in 'video_output' and 'file_managed' as stated in the original post.

I'm not sure if those two tables are being updated over and over, but it must be happening the first time the postback is received at least.

I could upload a different file immediately after, of longer duration and it will postback fine. It appears to be an issue with specific files (and only a handful at that). I can repeat the process over and over with the same result. These files do process without error on Zencoder, and they are ftp'd back successfully.... so I'm still thinking it might be something to do with the construction of the postback response and specific mime types, or string/char combinations that are specific to these problem files - but I can't see a pattern....?

Tsubo’s picture

Tsubo commented

Clutching at straw here, as I've pushed this module live on a production site.

Looking at a Zencoder Response that doesn't timeout - and everything works - I can see it's constructed of three chunks (output, input, job). I put each value pair in the array on a line for clarity.

This response worked ok:

{"output":{"file_size_in_bytes":9854389,
"audio_codec":"aac",
"duration_in_ms":61578,
"label":"video-2883",
"frame_rate":25.0,
"md5_checksum":null,
"channels":"2",
"total_bitrate_in_kbps":1278,
"url":"https://zencoder-live.s3.amazonaws.com/o/20120725/0ec5cd78dfecc8dcf7c4aec32a4096d0/notranscodetest_mp4_1343212894.mp4?AWSAccessKeyId=AKIAI456JQ76GBU7FECA&Signature=nDDQ17YOUniLzP9jA1AABskJwPQ%3D&Expires=1343299328",
"width":620,
"format":"mpeg4",
"video_bitrate_in_kbps":1218,
"video_codec":"h264",
"height":350,
"audio_sample_rate":44100,
"state":"finished",
"id":43070469,
"audio_bitrate_in_kbps":60},


"input":{"file_size_in_bytes":10693107,
"audio_codec":"aac",
"duration_in_ms":61532,
"frame_rate":25.0,
"md5_checksum":null,
"channels":"2",
"total_bitrate_in_kbps":1384,
"width":852,
"format":"mpeg4",
"video_bitrate_in_kbps":1224,
"video_codec":"h264",
"height":480,
"audio_sample_rate":44100,
"state":"finished",
"id":23083804,
"audio_bitrate_in_kbps":160},

"job":{"created_at":"2012-07-25T10:41:35Z",
"test":false,
"updated_at":"2012-07-25T10:42:08Z",
"submitted_at":"2012-07-25T10:41:35Z",
"pass_through":null,
"state":"finished",
"id":23089300}}

This one timed out:

{"output":{"video_bitrate_in_kbps":804,
"audio_codec":"aac",
"duration_in_ms":609087,
"frame_rate":25.0,
"md5_checksum":null,
"channels":"2",
"state":"finished",
"audio_bitrate_in_kbps":61,
"file_size_in_bytes":66153484,
"width":620,
"format":"mpeg4",
"url":"https://zencoder-live.s3.amazonaws.com/o/20120725/6a4186b073737b59c84a888e9ee9f8e5/seabreeze_view-h.264_lan_mp4_1343232493.mp4?AWSAccessKeyId=AKIAI456JQ76GBU7FECA&Signature=nb7Q%2BTbhcOa6fQsMw2ED7ueaLJE%3D&Expires=1343320524",
"video_codec":"h264",
"height":348,
"label":"video-2894",
"total_bitrate_in_kbps":865,
"audio_sample_rate":48000,
"id":43097635},

"input":{"video_bitrate_in_kbps":1399,
"audio_codec":"aac",
"duration_in_ms":609040,
"frame_rate":25.0,
"md5_checksum":null,
"channels":"2",
"state":"finished",
"audio_bitrate_in_kbps":109,
"file_size_in_bytes":115247638,
"width":854,
"format":"mpeg4",
"video_codec":"h264",
"height":480,
"total_bitrate_in_kbps":1508,
"audio_sample_rate":48000,
"id":23098087},

"job":{"created_at":"2012-07-25T16:08:13Z",
"test":false,
"updated_at":"2012-07-25T16:35:24Z",
"pass_through":null,
"submitted_at":"2012-07-25T16:08:13Z",
"state":"finished",
"id":23103583}}

In the first one, the input and output chunks and structured identically and in the same order. In the second they are structured in a different order.

Is there anything in the way the postback handler processes the response that assumes they will always be in the same order?

Tsubo’s picture

Tsubo commented

Ignore last comment. Silly question.

Just realised that our Cron is on a tab and set to run every 15 mins. The transcoding time for the particular file I've been having issues with (and testing with) is about 20mins. This means cron will run again before the postback of files from the previous cron.

Related to http://drupal.org/node/1673378 perhaps?

Jorrit’s picture

Jorrit commented

The thing I notice is that the failing video is much larger than the successful video. When you go to "http://yourdrupalsite/admin/reports/status/php", what is the value for max_execution_time ?

The file_managed entry is already created when the request is sent to Zencoder, so the fact that it exists is expected. The file size is added later. Are you sure that the file size of the converted file is exactly the size it is supposed to be? I am thinking it is smaller, because PHP times out while downloading the converted file. Look at the output -> file_size_in_bytes entry in the postback JSON to determine what the right filesize should be. In the case of the failing postback, it should be 66153484 bytes which is around 65 MB.

Tsubo’s picture

Tsubo commented

I've checked filesize of the returned file which is 66153770 bytes which looks slightly longer than it should be - but about right. It shows up slightly different depending on file system obviously (server, local etc). But it doesn't appear to be truncated in any way. I played it start to finish and it matches the original uploaded file.

PHP max_execution_time is set at '30'..... which would be well short if your suggesting this would need to longer than the required ftp transfer time.

However, I do have files that are considerably larger (over 350Mb) that postback ok? And of course I'm uploading these files in the first place - all without issue.... but I'll give a try.

Jorrit’s picture

Jorrit commented

So you're saying that just a couple of files fail consistently? Could I get those files?

Tsubo’s picture

Tsubo commented

Here's a link to one of them:

http://eurovisionshowcase.com/sites/default/files/public/videos/original...

Just looking at my Zencoder notification history today and looks as if the issue is broader than I thought.

I have some users already using the video upload/transcoding feature on the live site. Some files were uploaded this morning, processed ok, returned via ftp ok, flag in the video_queue in updating to '10', video_output looks good, and everything is playing fine on the site. But Zencoder is still getting a timeout 'status: failed' in the notification history and then continuing to try and send the postback? It's just not getting the HTTP OK response as it should.

Jorrit’s picture

Jorrit commented

You keep saying that files are returned via FTP, but that is not the case (anymore). Zencoder stores these files temporarily on their S3 account and then they are transfered by the postback code to the location that you selected. From what location are you serving your video videos?

Tsubo’s picture

Tsubo commented

Ahh. My mistake. Both source and output videos are on our server (not S3).

Jorrit’s picture

Jorrit commented

How many and what kind of presets do you have?

Jorrit’s picture

Jorrit commented

Never mind, I have been able to reproduce it. It has to do with Zencoder not waiting long enough for the notification handler to return a response. I am going to add code that makes sure that the long-lasting copy operations are not performed when the destination files already exist. In this situation, the first notification still fails, but the second one will be fast (because the files have already been copied) and the notification will succeed.

Within the next 12 hours, there will be a new 7.x-2.x-dev release with the fix. Could you install it and test it? You can go to Zencoder and have it re-transmit the failed notifications. As I said, if it fails the first time after you click "Resend Notification", try it a second time. It should work then.

Tsubo’s picture

Tsubo commented

Great news! Was beginning to think I was mad :)

Will test and report back as soon as the new version is available.

Thanks for all your effort on this. Much appreciated.

Tsubo’s picture

Tsubo commented

Just updated to the latest dev release, and run some tests (using the same test file). Still getting the same result. 'video_queue' still at status '5'....and filezise/duration tables still at '0'. Manually re-sending the notifications from Zencoder multiple times doesn't seem to help. Still timing out....

Jorrit’s picture

Jorrit commented

That is disappointing :( The only option I have left is for me to take a look at your site and try some things using the Devel module.

Tsubo’s picture

Tsubo commented

Have sent you a PM with URL/account login details.

Jorrit’s picture

Jorrit commented

Could you try the next dev release?

Tsubo’s picture

Tsubo commented

Have tested the latest dev version which looks to have solved it. Based on the drupal log, it's still taking a few postback attempts..... but none the less got there in the end. :-)

Many Thanks.

Jorrit’s picture

Jorrit commented
Status: Postponed (maintainer needs more info) » Fixed

For some reason, your server kills the execution of the script right after the copy() operation. You may want to look at the Apache fastcgi timeout settings.

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.