Plugin: Sage Job Queue (SJQ) v3

[MitchSchaft]

Cool, thanks.

[evilpenguin]

Originally Posted by Slugger

I just tried to reproduce the problem on my install, but was unable to. I just wrote a program that dumped 10240 lines of output to stdout and the task client gleefully flushed all 10240 lines (in two separate flushes) to the server and the server wrote them to the db with no issues. Since I can't reproduce the problem, I'm going to need someone who can to get the server side exception corresponding to the task client exceptions EP provided above.

I captured the logs that contained the relevant info for an error. I also attached a zip of the entire logs if you need to see some more.

Jetty Request.log
127.0.0.1 -  -  [05/Dec/2009:22:50:04 +0000] "POST /sjq/SJQ?proto=4&cmd=writeLog HTTP/1.1" 500 3333 "-" "SageTV SJQc/3.0.0.655 Java/1.6.0_10"
127.0.0.1 -  -  [05/Dec/2009:22:50:04 +0000] "POST /sjq/SJQ?proto=4&cmd=writeLog HTTP/1.1" 500 3333 "-" "SageTV SJQc/3.0.0.655 Java/1.6.0_10"
127.0.0.1 -  -  [05/Dec/2009:22:50:07 +0000] "GET /sjq/SJQ?proto=4&cmd=showQ&sid=-798703310 HTTP/1.1" 200 130814 "http://127.0.0.1:8080/sjq/sjq/C7A0C9438C9B3D1987C486F64DA690F8.cache.html" "Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) AppleWebKit/532.0 (KHTML, like Gecko) Chrome/3.0.195.33 Safari/532.0"


Wrapper.log:
INFO   | jvm 1    | 2009/12/05 14:50:04 | Exception in thread "Thread-27" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	... 3 more

[MitchSchaft]

Do I add it to the client file like this?

COMSKIP {
   :RESOURCES 100 # Up to 4 comskips can be run simultaneously (every client has exactly 100 resources available)

   # CPU priority to be used for this task process; one of LOW, NORMAL, HIGH (case sensitive)
   :CPU "NORMAL"   # Default is NORMAL if not specified

   "C:/Program Files/SageTV/SageTV/ComskipMonitor/comskip80_025/comskip.exe \"%c%\""

   -ini %C:/Program Files/SageTV/SageTV/ComskipMonitor/comskip80_025/comskip.exe/comskip.ini%
}

It gives a "Unexpected '-' on line 9" error in the client log.

[Slugger]

Originally Posted by MitchSchaft

Do I add it to the client file like this?

COMSKIP {
   :RESOURCES 100 # Up to 4 comskips can be run simultaneously (every client has exactly 100 resources available)

   # CPU priority to be used for this task process; one of LOW, NORMAL, HIGH (case sensitive)
   :CPU "NORMAL"   # Default is NORMAL if not specified

   "C:/Program Files/SageTV/SageTV/ComskipMonitor/comskip80_025/comskip.exe \"%c%\""

   -ini %C:/Program Files/SageTV/SageTV/ComskipMonitor/comskip80_025/comskip.exe/comskip.ini%
}

It gives a "Unexpected '-' on line 9" error in the client log.

All on one line. And I believe it's --ini=C:/Program Files/...

[Slugger]

Originally Posted by evilpenguin

I captured the logs that contained the relevant info for an error. I also attached a zip of the entire logs if you need to see some more.

Jetty Request.log
127.0.0.1 -  -  [05/Dec/2009:22:50:04 +0000] "POST /sjq/SJQ?proto=4&cmd=writeLog HTTP/1.1" 500 3333 "-" "SageTV SJQc/3.0.0.655 Java/1.6.0_10"
127.0.0.1 -  -  [05/Dec/2009:22:50:04 +0000] "POST /sjq/SJQ?proto=4&cmd=writeLog HTTP/1.1" 500 3333 "-" "SageTV SJQc/3.0.0.655 Java/1.6.0_10"
127.0.0.1 -  -  [05/Dec/2009:22:50:07 +0000] "GET /sjq/SJQ?proto=4&cmd=showQ&sid=-798703310 HTTP/1.1" 200 130814 "http://127.0.0.1:8080/sjq/sjq/C7A0C9438C9B3D1987C486F64DA690F8.cache.html" "Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) AppleWebKit/532.0 (KHTML, like Gecko) Chrome/3.0.195.33 Safari/532.0"


Wrapper.log:
INFO   | jvm 1    | 2009/12/05 14:50:04 | Exception in thread "Thread-27" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
INFO   | jvm 1    | 2009/12/05 14:50:04 | 	... 3 more

What I need to see is the server side exception dump. I need to see the contents of 2009_12_05.stderrout.log. This is the log file that will contain the exception dump that's causing the task client to receive the HTTP 500 errors. This file should be in the same location as 2009_12_05.request.log. If it's not there then you have not enabled Jetty debug logging. You will need to first stop SageTV, enable SageTV debug logging then go to base install dir, edit JettyStarter.properties and add "$(jetty.home)/etc/jetty-logging.xml" to the jetty.configfiles property. Then scroll down a bit and uncomment the line that reads DEBUG=true then restart SageTV. Then reproduce and get me that 2009_12_05.stderrout.log file. It should have an exception dumped at the same time you see these types of errors:

127.0.0.1 -  -  [05/Dec/2009:22:50:04 +0000] "POST /sjq/SJQ?proto=4&cmd=writeLog HTTP/1.1" 500 3333 "-" "SageTV SJQc/3.0.0.655 Java/1.6.0_10"

My other concern (maybe), is this line:

127.0.0.1 -  -  [05/Dec/2009:22:50:07 +0000] "GET /sjq/SJQ?proto=4&cmd=showQ&sid=-798703310 HTTP/1.1" 200 130814 "http://127.0.0.1:8080/sjq/sjq/C7A0C9438C9B3D1987C486F64DA690F8.cache.html" "Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) AppleWebKit/532.0 (KHTML, like Gecko) Chrome/3.0.195.33 Safari/532.0"

The server is returning an active queue response of 130814 bytes. That seems awfully large, but it's a 200 response (HTTP OK code) so everything looks ok. Were there a lot of tasks in the queue at the time of that request? (Like maybe 30 or 40, I'm guessing?)

Anyway, I need that 2009_12_05.stderrout.log to see the server side exception.

[evilpenguin]

Originally Posted by Slugger

What I need to see is the server side exception dump. I need to see the contents of 2009_12_05.stderrout.log.

K, i'll grab it tomorrow.

Originally Posted by Slugger

The server is returning an active queue response of 130814 bytes. That seems awfully large, but it's a 200 response (HTTP OK code) so everything looks ok. Were there a lot of tasks in the queue at the time of that request? (Like maybe 30 or 40, I'm guessing?)

Yeah, I've got a *huge* backlog of encodes.

[Slugger]

I think I know the problem... I just remembered I had some problems originally with the task client logging when I started work on SJQv3 back in September because one of the first changes I made was to increase the client task log buffer significantly as a way to reduce constant network traffic between the client and server.

Anyway, long story short, by default Jetty only accepts POST requests of 200,000 bytes max. 5120 lines would be on avg twice that size so I'm pretty sure you've hit this limitation. You need to override Jetty's default and tell it to accept bigger form posts. For the Jetty plugin, you do this by adding the following line to JettyStarter.properties (must stop SageTV and restart for this change to take effect):

org.mortbay.jetty.Request.maxFormContentSize=5242880

I put that line right under the commented out jetty.home line and totally forgot about it until just a few moments ago. I'd still recommend following through with producing the stderrout.log file in case this isn't the issue, but I'm fairly certain it is (ha! Another quote from the software developer's guide to self-destruction)

When you're making the changes to produce the log files add that line into JettyStarter.properties and I'm fairly certain you'll have eliminated those flushing errors. Please do report back your results so that I can get jreichen to add the line to the next version of the Jetty plugin.

I set mine to 5MB, which is probably overkill, a value of 2 or even 1MB should probably be enough, but 5MB should mean that the value will never have to be adjusted again.

[evilpenguin]

Nice catch

I'll catch the log on the first football game tomorrow and then try the fix on the 2nd one.

[ohpleaseno]

when you guys refer to flushing, are you talking about when all the items in the active queue go directly to completed at once?

[Slugger]

Nope, we're talking about the errors recently reported where the task client is failing to flush the buffered output of commands being run back to the server for logging.

Unfortunately, one of the issues with the user forums that I don't like is that many different, unrelated conversations get spliced together in support threads like the one for SJQv3. The only relation between all the posts is that they're all about SJQv3, but typically at any one time there are usually a half dozen or so different conversations about SJQv3 going on in the thread. I've linked to the start of the conversation being discussed, but you'll have to maneuver around the thread to follow along with the specifics of this conversation. If the fix I've suggested indeed works, I'll be adding the specifics to the user guide and warning everyone to make the change anyway. And actually, regardless, the change I mention to JettyStarter.properties is required anyway to avoid the issue I speak of even if it's not the issue EP is experiencing since it's a known issue anyway (that I hit early on in SJQv3 development).

[ohpleaseno]

so, the fact that all of the sudden mediashrink is now queuing up recordings properly and running through them correctly is all voodoo crazy magic?

[ohpleaseno]

AND it also now is working on my Win7 box which wasn't ever working before.

No more "No Audio and Video" problem for either box.

Win 7 box - MediaShrink v2.0c

WHS - MediaShrink v2.0dev

both using SJQ in service mode.

SJQ build 679

----

on edit, I should reserve judgment until after it runs through a few recordings though. For now though, I'm in territory that never happened before.

[nyplayer]

Tip,Tip,Tip

All these SJQ MediaShrink problems go away if you run the latest MediaShrink from a from a batch file.

[nyplayer]

Slugger,

I noticed when you use the _RELINK it marks the show as an Archived is this by design... I guess I would like to keep the file Status as is. If its manual keep it as manual if its not archived or manual keep it that way.

[Slugger]

Originally Posted by nyplayer

Tip,Tip,Tip

All these SJQ MediaShrink problems go away if you run the latest MediaShrink from a from a batch file.

Or directly call mediaEngine.exe, as EP suggested as well. Only problem I'm seeing with the direct mediaEngine call is that the process priority is not being set properly.

[ohpleaseno]

Originally Posted by nyplayer

Tip,Tip,Tip

All these SJQ MediaShrink problems go away if you run the latest MediaShrink from a from a batch file.

tried it. wouldn't work for me.

[Slugger]

Originally Posted by nyplayer

Slugger,

I noticed when you use the _RELINK it marks the show as an Archived is this by design... I guess I would like the keep the file Status as is. If its manual keep it as manual if its not archived or manual keep it that way.

Not so much by design, as by force. It's a product, I believe, of relinking the airing info to a different media file. I'm not actually explicitly setting the archive flag, Sage is doing it all on its own. _UNARCHIVE task can be used to unset it, if so desired (just make sure it has a lower priority than the _RELINK so it runs after the _RELINK task).

[ohpleaseno]

Originally Posted by Slugger

Or directly call mediaEngine.exe, as EP suggested as well. Only problem I'm seeing with the direct mediaEngine call is that the process priority is not being set properly.

I'm calling mediashrink.exe and it's working fine. I have NO idea what changed between yesterday and today except that it started working after I included the code from your flushing fix.

I know it's unrelated, but hey, I'm golden now.

[nyplayer]

Originally Posted by ohpleaseno

tried it. wouldn't work for me.

Sample batch

set type=mp4
cd "c:\mediashrink"
c:
start /I /LOW /MIN /WAIT mediaShrink.exe "%~f1" /batch /InPlace /divx /onePass /cliBitrate 1000 /horizontalScale 512 /aac /%type%
if not exist "%~d1%~p1%~n1.%type%" exit 1
if exist "%~d1%~p1%~n1.%type%" exit 0

[ohpleaseno]

Originally Posted by nyplayer

Sample batch

set type=mp4
cd "c:\mediashrink"
c:
start /I /LOW /MIN /WAIT mediaShrink.exe "%~f1" /batch /InPlace /divx /onePass /cliBitrate 1000 /horizontalScale 512 /aac /%type%
if not exist "%~d1%~p1%~n1.%type%" exit 1
if exist "%~d1%~p1%~n1.%type%" exit 0

what is your client ruleset?