Plugin: Sage Job Queue (SJQ) v3

[superdodge]

Originally Posted by toricred

Make sure that you're not calling ShowAnalyzer until the recording is finished. It's currently having problems with analyzing a file that is still recording. Jere is aware of the issue and it is included in the current bug list for the product.

What happens with this bug? The commercials are identified correctly and it shows up in the history section of ShowAnalyzer.

This seems to be an issue with SJQ to me, but I could be wrong.

[Slugger]

Originally Posted by superdodge

What happens with this bug? The commercials are identified correctly and it shows up in the history section of ShowAnalyzer.

This seems to be an issue with SJQ to me, but I could be wrong.

It could very well be an SJQ (task client) bug, but that depends on you verifying exactly what's happening. Is ShowAnalyzer crashing out? If so, when it does then does the task client crash out with it? Or, more likely, if ShowAnalyzer is crashing out then the native execution thread is probably dying in SJQ meaning the final status isn't reported back properly (although the task client will still process future work). Again, it all comes down to some more investigation on your part. I need to know if ShowAnalyzer is indeed dying.

[toricred]

I was thinking you were saying that it never finishes in SAV1's UI. If that's not the case then ignore my comment.

[nyplayer]

Slugger,

One thing I have noticed If I have something to use 40% resources so that only 2 run at 1 time. IF SJQ runs a scan and nothing is running it will schedule more than 2. I have had occasions of 4 jobs running at 40%. I guess it is a matter of timing.

[Slugger]

I'd like to see the logs when this happens. The QueueLoader will load all jobs into the queue, that's expected. The resources check is done each time a client connects searching for work. When there aren't enough resources free for a client to do a specific type of task it should tell you each time the client connects that it can't run certain tasks. If that's not happening I'd like to see the logs.

[nyplayer]

Slugger,

Could this be causing the problem?

2010-01-11 12:12:46,640 INFO  [SJQServlet]: Servlet POST request completed [15ms]
2010-01-11 12:12:46,828 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:12:50,250 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:12:52,734 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:01,406 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:01,546 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:01,640 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:16,859 WARN  [DataStore]: DataStore pool timeout expired! '16416625@qtp-16317156-13' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:13:20,468 WARN  [DataStore]: DataStore pool timeout expired! '24364335@qtp-16317156-8' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:13:22,984 WARN  [DataStore]: DataStore pool timeout expired! '7463685@qtp-16317156-17' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:13:29,843 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:29,843 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:31,406 WARN  [DataStore]: DataStore pool timeout expired! '16328375@qtp-16317156-11' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:13:31,531 WARN  [DataStore]: DataStore pool timeout expired! '28927063@qtp-16317156-6' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:13:31,640 WARN  [DataStore]: DataStore pool timeout expired! '20912263@qtp-16317156-14' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:13:31,968 INFO  [DataStore]: Flushed 16 log message(s) in 2125ms
2010-01-11 12:13:31,968 INFO  [SJQServlet]: Servlet POST request completed [2125ms]
2010-01-11 12:13:32,015 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:13:33,656 INFO  [DataStore]: Flushed 5 log message(s) in 1641ms
2010-01-11 12:13:33,656 INFO  [SJQServlet]: Servlet POST request completed [1672ms]
2010-01-11 12:13:59,843 WARN  [DataStore]: DataStore pool timeout expired! '28853156@qtp-16317156-9' did not return connection within 30 seconds!  Adding a replacement connection to the pool.
2010-01-11 12:14:03,921 INFO  [InternalTaskClient]: Run completed [50546ms]
2010-01-11 12:14:03,921 WARN  [DataStore]: Thread '28853156@qtp-16317156-9' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,921 INFO  [SJQServlet]: Servlet POST request completed [34078ms]
2010-01-11 12:14:03,921 WARN  [DataStore]: Thread '20912263@qtp-16317156-14' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,921 INFO  [SJQServlet]: Servlet POST request completed [62281ms]
2010-01-11 12:14:03,937 WARN  [DataStore]: Thread '28927063@qtp-16317156-6' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,937 INFO  [SJQServlet]: Servlet POST request completed [62406ms]
2010-01-11 12:14:03,937 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:14:03,937 INFO  [ClientParser]: MAPPING: M:\sagem => \\169.254.5.12\M$\sagem
2010-01-11 12:14:03,937 INFO  [ClientParser]: MAPPING: N:\sagen => \\169.254.5.12\N$\sagen
2010-01-11 12:14:03,953 WARN  [DataStore]: Thread '16328375@qtp-16317156-11' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,953 INFO  [SJQServlet]: Servlet POST request completed [62547ms]
2010-01-11 12:14:03,953 WARN  [DataStore]: Thread '7463685@qtp-16317156-17' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,953 INFO  [SJQServlet]: Servlet POST request completed [71219ms]
2010-01-11 12:14:03,953 WARN  [DataStore]: Thread '24364335@qtp-16317156-8' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,953 INFO  [SJQServlet]: Servlet POST request completed [73703ms]
2010-01-11 12:14:03,953 WARN  [DataStore]: Thread '16416625@qtp-16317156-13' attempted to return a timed out connection!  Dropping connection.
2010-01-11 12:14:03,968 INFO  [SJQServlet]: Servlet POST request completed [77140ms]
2010-01-11 12:14:03,968 INFO  [SJQServlet]: Checking client '169.254.5.240': 60 resources free.
2010-01-11 12:14:03,984 INFO  [SJQServlet]: Servlet POST request completed [47ms]
2010-01-11 12:14:03,984 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2010-01-11 12:14:04,062 INFO  [MediaFileQueueLoader]: Run completed [78406ms]
2010-01-11 12:14:04,093 INFO  [VacuumCleaner]: Thread finished [0ms]
2010-01-11 12:14:04,125 WARN  [FileCleaner]: Skipping because file cleaner settings are empty!

[Slugger]

Originally Posted by nyplayer

Slugger,

One thing I have noticed If I have something to use 40% resources so that only 2 run at 1 time. IF SJQ runs a scan and nothing is running it will schedule more than 2. I have had occasions of 4 jobs running at 40%. I guess it is a matter of timing.

Having read this again, let me see if I'm following this. If there's nothing running (even if there is), the queue will load all 4 jobs and put them all in WAITING state, that's expected, that's how it should work. The key is that if a client is set to require 40 resources to run those tasks then you should never see more than two of those tasks in RUNNING state at one time on a single client configured to use 40 resources per instance of the task (the other two should remain in WAITING until the client finishes one of the tasks in RUNNING state). If this isn't what you're seeing then there's a problem.

[Slugger]

2010-01-11 12:14:03,921 INFO [SJQServlet]: Servlet POST request completed [62281ms]

Match the time stamp with the request in your Jetty request log (subtract the 62 seconds probably, so this would correspond to the request in the Jetty log form Jan 11 12:13:01). No request to the SJQ server should take anywhere near 60 seconds to complete. This is a problem, is it causing the original problem? I don't think so, but maybe. First you need to figure out why the SJQ server is taking 60 seconds to respond to requests.

[Peter_h]

Originally Posted by Slugger

It looks like a wiz.bin problem, but you'll want to confirm that by checking the full path of the file in your STV or on the web server, etc. If they show the same (incorrect) path then the problem is in your wiz.bin. I suspect that this is the case because the value SJQ uses is just pulled from wiz.bin. However, confirm that via another source.

You have two options to handle this. First, you can use the :MAPDIR setting in SJQ to tell the client to map one dir to another. This should work fine, but if it is indeed a wiz.bin issue then you're going to have other problems (like trying to watch the recording isn't going to work because Sage thinks the file is somewhere it's not). But as far as SJQ goes, the :MAPDIR option should work just fine. My recommended solution, however, is to get the paths right in wiz.bin since not doing so is going to cause you way more problems beyond SJQ.

I would not use _MOVEREC task here because _MOVEREC must always copy the file somewhere and even if it's a copy to the same dir, it will do a read/write of the entire physical file (as opposed to a rename operation). You definitely don't want to use _MOVEREC for this scenario.

Hey Slugger,

Update: It turned out to be a wiz.bin problem. I was able to repair the wiz.bin using the advanced_video_file_recovery=true in the properties file. After that was all fixed, I cleared the active queue grid in SJQ and then did another media scan in SJQ. Then the files were being processed correctly in SJQ without the error I reported.

[Slugger]

Snapshot 753 now available. Snapshot 753 contains a new feature: the ability to use custom java calls as tests. I'd consider this feature alpha quality, but thought I'd mention it to those who want to help test it out. Nothing in the User Guide yet, but all the gory details on how to use it are in this issue ticket. If you do take a walk on the bleeding edge of SJQ and give this a shot, please report back your results. I'm quite sure bugs exist in this feature, but I need testers to find them.

[nyplayer]

Slugger,

This is what is happening it is scheduling correctly 2 at a time at 40% resources.... but the timeouts are causing SJQ to lose connection and lose track of the running tasks and schedules 2 more so then in task manager I see 4 processes but SJQ only shows the last 2.

I am running comskip etc.. over a network so sometimes the network reaches up tp 90% and above usage.

I believe this causes the connection to sometimes timeout. I can work around this by some parameters in comskip to run a little slower... right now I have it at full speed.

SJQ Task Client v3.0.1.705
Using 'C:/sjqc' as location for configuration file...
Exception in thread "Thread-67" java.lang.RuntimeException: java.io.IOException:
 Server returned HTTP response code: 500 for URL: http://169.254.5.12:9000/sjq/S
JQ?proto=4&cmd=writeLog
        at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source
)
        at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL:
 http://169.254.5.12:9000/sjq/SJQ?proto=4&cmd=writeLog
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown So
urce)
        ... 3 more
Exception in thread "Thread-72" java.lang.RuntimeException: java.io.IOException:
 Server returned HTTP response code: 500 for URL: http://169.254.5.12:9000/sjq/S
JQ?proto=4&cmd=writeLog
        at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source
)
        at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL:
 http://169.254.5.12:9000/sjq/SJQ?proto=4&cmd=writeLog
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown So
urce)
        ... 3 more

[Slugger]

I need the server side exceptions causing these client side exceptions. Likely, you will have to enable Jetty debug logging and get the exceptions logged by Jetty. Each time an IOMonster thread dies it leaves the process that was running (comskip in your case, it seems) hung because nothing is consuming the output.

The problem is usually Jetty not configured to handle requests greater than 200,000 bytes, but SJQ v3.0.1 addressed that issue so unless you increased the buffer size in your sjqc.properties file to over 200,000 and didn't increase Jetty's MAX POST setting, then this is not likely what you're hitting. Therefore, I need the server side errors and exceptions causing the 500 HTTP response. I have no way to reproduce 60 second response times (or at least no way that I'm willing to try on my lone SageTV system) so you're going to have to enable Jetty debug logging and get the server side exceptions to me for analysis.

[Tropicaljoe]

Slugger, Could SJQ be used for other external apps? Here is what I am looking to do. I want to be able to run a defrag on my drives while using your rulesets. It would be nice to be able to run the defrag only if no recordings are running, and no recordings are scheduled for the next hour or so. I believe that if I tried this now, it would probably run, but loop forever as the conditions would be true most of the time. Is something like this even possible?

[Slugger]

It's possible, but requires care to avoid an endless loop of the task running. This is not really what SJQ is designed for, but it can be used as such. Today's my first day back to work in almost 3 weeks so they've got me busy today so I don't have time to write ruleset examples, but suffice it to say it's possible.

[[JiF]Mike]

Hello, first just wanna say how great this addon is! Wish I had taken the time to play around with it before. But anyway on to my little problem...bug perhaps?

I have a few drives in my sagetv pc for recordings. I've recently added a larger one that I decided to dedicate to recording and so I did not create a folder on this drive, I just let the recording happen at the root. I also got comskip setup and working. So I decided to get a sjq client going on another pc in the house since I have a lot of shows to catch up with the comskip. This remote pc can handle the files that exist in: \\sagetv\d\tv without a problem. However when it tries to grab the files at \\sagetv\h it says "file not found" and the log tells me why. I just have no idea how to fix it! Here's my client config and the resulting logs for media files.

Client Config

# Client Options
:MAPDIR "H:\\" "\\\\sagetv\\h\\"
:MAPDIR "D:\\tv" "\\\\sagetv\\d\\tv"

COMSKIP {
   :RESOURCES 50 # Up to 2 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

   # Comskip returns 1 on success instead of the universally accepted zero; tell SJQ that
   # a return code of 1 means success instead of the default value of zero
   :RETURNCODE 1

   "C:/comskip/comskip.exe \"%c%\""
}

One note, I have tried the MAPDIR with the trailing \\ and without, but the error remains the same.

Failed Media File Log

Tue Jan 12 16:03:48 EST 2010: Starting task with priority 5/1/10
Executing command line: C:/comskip/comskip.exe "\\sagetv\hDirtyJobs-MapleSyrupMaker-4189308-0.ts"
The commandline used was:
C:\comskip\comskip.exe \\sagetv\hDirtyJobs-MapleSyrupMaker-4189308-0.ts
Opening \\sagetv\hDirtyJobs-MapleSyrupMaker-4189308-0.ts

Comskip 0.80.030, made using:
mpeg2dec-0.4.0 - by Michel Lespinasse <walken@zoy.org> and Aaron Holtzman
No such file or directory - could not open file \\sagetv\hDirtyJobs-MapleSyrupMaker-4189308-0.ts

You can see that the path is missing the "\" I just don't know why!

Good Media File Log

Tue Jan 12 14:41:20 EST 2010: Starting task with priority 5/1/10
Executing command line: C:/comskip/comskip.exe "\\sagetv\d\tv\LittlePeopleBigWorld-MakingtheGrade-3799027-0.mpg"
The commandline used was:
C:\comskip\comskip.exe \\sagetv\d\tv\LittlePeopleBigWorld-MakingtheGrade-3799027-0.mpg
Opening \\sagetv\d\tv\LittlePeopleBigWorld-MakingtheGrade-3799027-0.mpg
Using C:\comskip\comskip.ini for initiation values.
Commercials were found.

Comskip 0.80.030, made using:
mpeg2dec-0.4.0 - by Michel Lespinasse <walken@zoy.org> and Aaron Holtzman
 0:30:00 - 87 frames in 1.21 sec (71.90 fps), 1.21 sec (71.90 fps), 0%
 0:30:02 - 130 frames in 2.23 sec (58.30 fps), 1.01 sec (42.57 fps), 0%
 0:30:02 - 137 frames in 3.23 sec (42.41 fps), 1.00 sec (7.00 fps), 0%
 0:30:02 - 146 frames in 4.36 sec (33.49 fps), 1.12 sec (8.04 fps), 0%
 0:30:04 - 191 frames in 5.40 sec (35.37 fps), 1.04 sec (43.27 fps), 0%
...etc...

I'm hoping I've just missed something!

[Slugger]

My initial guess is that it's a bug. I'm back to work after 2.5 weeks vacation this week so there is no time for me to look at this during the day and my evenings are booked this week so it's probably the weekend before I can sit down, try to reproduce it, then look at the code to fix it. My first guess at a possible quick fix would be to change your dir mapping to something like this:

:MAPDIR "H:" "\\\\sagetv\\h\\"

or if that don't work, try:

:MAPDIR "H:" "\\\\sagetv\\h"

Be careful when trying these, I'd restrict your rule to only work on one specific recording... but give that a shot and let me know. If one of those do happen to work then I have a fairly good idea what the bug is in the code, but, as I say, it's going to be a few days before I can even start to take a closer look at it.

[[JiF]Mike]

Looks like that did the trick. I changed it to:

 :MAPDIR "H:" "\\\\sagetv\\h\\"

Tue Jan 12 16:55:55 EST 2010: Starting task with priority 5/1/10
Executing command line: C:/comskip/comskip.exe "\\sagetv\h\LittlePeopleBigWorld-UnhappyTrails-3917064-0.mpg"

Thank you!

[Peter_h]

I'm having a problem with my client machine not being able to process comskip jobs on my server.

Here is what I see in the logs.

Task Log: 3900847/COMSKIPSD

Thu Jan 14 20:34:23 HST 2010: Starting task with priority 5/1/10
Executing command line: C:/comskip/comskip.exe "\\Server\SageTV Recordings\30Rock-BlackLightAttack-3754433-0.mpg"
Comskip 0.80.027, made using:
mpeg2dec-0.4.0 - by Michel Lespinasse <walken@zoy.org> and Aaron Holtzman
Permission denied - could not open file \\Server\SageTV Recordings\30Rock-BlackLightAttack-3754433-0.mpg
The commandline used was:
C:\comskip\comskip.exe "\\Server\SageTV Recordings\30Rock-BlackLightAttack-3754433-0.mpg"

Opening \\Server\SageTV Recordings\30Rock-BlackLightAttack-3754433-0.mpg

and here are the client options

# Client options
COMSKIPSD {
   :RESOURCES 50 # Up to 2 comskipsd 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

   # Comskip returns 1 on success instead of the universally accepted zero; tell SJQ that
   # a return code of 1 means success instead of the default value of zero
   :RETURNCODE 1
   :MAXRUNRATIO 1

   "C:/comskip/comskip.exe \"%c%\""
}

I am running WHS server as the main server and the client is running XP. The client has access to the "SageTV Recordings" directory. I can access this directory from the client machine over the network and transfer files to and from the directory. I also tried copying the above file in question to the desktop on the client machine and it copied without issue.

The jobs processed locally by the server work fine. It seems like I am almost there but missing a setting somewhere. Can someone help?

[[JiF]Mike]

What account do you have the client service logging in as? If it is the local system account on the client machine, that account does not have access to the share that your file lives on.

Just go to "Services" on the client pc, open up the properties of the SJQC service and go to the "Log On" tab. Put in a user that has access to your share but remember the password can't be blank. Restart the service and try again.

[korben_dallas]

Can SJQ cause SageTV (running in application mode, not service mode) to gracefully exit? If x y z then exit/shutdown..