Plugin: SJQv4

[bikesquid]

Originally Posted by Slugger

Give it a shot on Win64, would you? And let me know if it starts up. The IDE itself will run on Win64, just the helper exe I created to launch it may or may not. If it doesn't, you could write a batch file that launched it for you. Alternatively, Eclipse env would work on Win64, but a lot more work involved setting up an Eclipse env to run SJQv4 scripts.

So if I start in the sagegroovy/bin directory and simply execute the commandline as:
sagegroovy -g c:\program files\sagetv\scripts\file_rename.groovy

and add the line:
def SJQ4_METADATA = ["SJQ4_ID":"1234566", "SJQ4_TYPE":"MediaFile"]

(with a valid SJQ4_ID value) it should run and put the log info on the screen?

.... I ask because that's not happening and I suspect it's because I'm an idiot... seeking validation.

[Slugger]

You don't put the file name on the command line (when using -g). I also suggest adding -s 192.168.1.1 (replace IP with IP running SJQ4 server).

So:

sagegroovy.exe -s 192.168.1.1 -g

That should bring up the GUI editor. Then open your Groovy script via File > Open...

Add the SJQ4_METADATA hashmap to the top of the script then press Ctrl+Enter to run the script (or select run from the Script menu). Output of the script will go to the bottom panel of the editor.

[rsagetv99]

Originally Posted by Slugger

I assume you're returning code 2 from the test script for these tasks? That marks them as 'skipped' in the database and by default skipped tasks purge themselves from the db after 24 hours. The amount of time tasks hang around in the db is configurable in the SJQ plugin config screen from the Sage STV. One day is the lowest you can go, and that's the default for skipped tasks. Completed tasks hang around for 7 days and failed tasks for 21 by default. Again, it's all configurable.

Yeah, return code 2. Will it keep track of processes that it already ran against and decided to skip, or am I going to see the same skipped jobs over and over again when the media_file_scan runs?

[Slugger]

Originally Posted by rsagetv99

Yeah, return code 2. Will it keep track of processes that it already ran against and decided to skip, or am I going to see the same skipped jobs over and over again when the media_file_scan runs?

You'll see them over and over again. Since SJQv4 is built around the Sage 7 event model, it doesn't keep track of what it's run in the past (as far as deciding if it should or shouldn't run it again). In SJQv4, if you put a task in the queue, it'll be assigned and executed.

Instead of detecting .avi or .edl, etc. in the comskip pretest, simply detect that in the media scanner script and don't queue up the comskip task for files that shouldn't be comskipped. This will prevent the build up of skipped tasks in the SJQ task queue. With that said, there shouldn't be any harm in allowing those tasks to queue up, but if you don't want that to happen then you've got to do the checks in the media scanner instead of the comskip pretest.

[rsagetv99]

Originally Posted by Slugger

Instead of detecting .avi or .edl, etc. in the comskip pretest, simply detect that in the media scanner script and don't queue up the comskip task for files that shouldn't be comskipped. This will prevent the build up of skipped tasks in the SJQ task queue. With that said, there shouldn't be any harm in allowing those tasks to queue up, but if you don't want that to happen then you've got to do the checks in the media scanner instead of the comskip pretest.

That's a good idea. Then I would only see the media_scan job. That will save some extra processing as well...

Thanks!

[bikesquid]

Originally Posted by Slugger

You don't put the file name on the command line (when using -g). I also suggest adding -s 192.168.1.1 (replace IP with IP running SJQ4 server).

So:

sagegroovy.exe -s 192.168.1.1 -g

That should bring up the GUI editor. Then open your Groovy script via File > Open...

Add the SJQ4_METADATA hashmap to the top of the script then press Ctrl+Enter to run the script (or select run from the Script menu). Output of the script will go to the bottom panel of the editor.

So here's what I'm getting instead...sagegroovy error.png which seems to be related to the 64bit....

As an aside, when doing the rename, it's working most of the time, but occasionally it's failing to delete the original file. I suspect it has to do with sage not releasing the file quite as quickly after recording stopped (the event trigger). I plan to add a wait period to hopefully fix it, but would also like to capture a errorlevel if there is one so I can proceed with options to try again or revert to the old name, etc. Is there a returnlevel for the moveFile command?

[Slugger]

Packaging error with that build, it's missing a required jar. Grab the 4.0.0.1403.2 build that's up there now.

[Slugger]

Originally Posted by bikesquid

Is there a returnlevel for the moveFile command?

You're using apache commons for the file move, right?

If so, you need to catch the IOException...

try {
   FileUtils.moveFile(src, target)
} catch(IOException e) {
   // This block only runs if the moveFile() call fails.
}

Do your error handling in the catch block. Why it failed is in the exception message (e.getMessage()), but I don't think you'd need to differentiate failure reasons (but maybe).

[bikesquid]

Originally Posted by Slugger

You're using apache commons for the file move, right?

If so, you need to catch the IOException...

try {
   FileUtils.moveFile(src, target)
} catch(IOException e) {
   // This block only runs if the moveFile() call fails.
}

Do your error handling in the catch block. Why it failed is in the exception message (e.getMessage()), but I don't think you'd need to differentiate failure reasons (but maybe).

Two thoughts that you probably have noodled around and have a strategy suggestion for.... Having thought about it more, I suspect it's actually someone was watching the show on another client, a situation I haven't addressed yet. If I do a 'return 1' on fail does that put the task back in the queue at the bottom so the task client can move on to the next task?

[Slugger]

Originally Posted by bikesquid

Two thoughts that you probably have noodled around and have a strategy suggestion for.... Having thought about it more, I suspect it's actually someone was watching the show on another client, a situation I haven't addressed yet. If I do a 'return 1' on fail does that put the task back in the queue at the bottom so the task client can move on to the next task?

return 1 will not put it back in the queue. Instead, in the catch block requeue a new task for it. Be careful though, because if the reason it's failing doesn't clear up rather quickly then you'll end up in an endless loop.

[K O]

I'm wondering if skipped items are being re-checked indefinitely. I have it setup to skip live TV (not manual and not favorite) that way incase it converts to a manual recording later, comskipping would start automatically. I think there's no way to pickup that the file is over, and so it never moves out of skiped status from the database. But I don't entirely understand how queue is processed.

Originally Posted by Slugger

Check to see if you're using the h2-1.2.145.jar (in your JARs) folder.

Yep, running h2-1.2.145.jar

Originally Posted by Slugger

This is a misconfiguration with one of your tasks. I don't think I've ever said these errors were harmless. If I did, then I misspoke. I mean they aren't harmless in that they cause damage, but it's a clear sign of a buggy Groovy script and/or a misconfigured task. Find out which task(s) are producing that output and fix it. Look at the task client log files for the time stamp given (probably a second or two earlier, actually) and then figure out which task is running at that time and then fix it so it doesn't constantly fail with a NullPointerException. Depending on what script is causing it, an NPE failure may send the the task right back to the queue and the cycle will continue forever. Scripts that cause NPEs are either buggy or misconfigured, either way something needs to be fixed, but before I can even try to diagnose the problem, I need to know what script is causing that output.

I cleared out the logs and the queue table in the database and restarted SageTV. I've watched it for a few days, and while it's not producing that Null Pointer error anymore, it's still making very large log files with dozens of lines per second that say:

===== Tue Apr 05 15:53:55 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties

In the SJQ.log, there's this every few seconds.

Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,666 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,666 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,682 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,682 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,682 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,682 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,682 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,682 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,697 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,697 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,697 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,697 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,697 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,697 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,713 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,713 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,713 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,713 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,713 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,713 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,728 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,728 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,728 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,728 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,728 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,728 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,744 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,744 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,744 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,760 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,760 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,760 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,760 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,760 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,760 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,760 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,760 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,760 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,775 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,775 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,775 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,775 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,775 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,775 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,791 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,791 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,791 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,791 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,791 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,791 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,791 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,791 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,791 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,807 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,807 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,807 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,807 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,807 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,807 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,807 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,807 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,807 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,822 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,822 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,822 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,822 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,822 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,822 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,838 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,838 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,838 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,838 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,838 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,838 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,838 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,838 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,838 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,853 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,853 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,853 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,853 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,853 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,853 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,853 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,853 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,853 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,869 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,869 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,869 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,869 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,869 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,869 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,869 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,869 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,869 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,885 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,885 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,885 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,885 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,885 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,885 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,885 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,885 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,885 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,900 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,900 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,900 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,900 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,900 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,900 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,916 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,916 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,916 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,916 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,916 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,916 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,916 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,916 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,916 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,916 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,916 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,916 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,932 WARN  [TaskQueue]: Client is already running max instances of 'COMSKIPTIMER'; skipping: Client[host=whs:23344,state=ONLINE,lastUpdate=Tue Apr 05 16:22:51 CDT 2011]
2011-04-05 16:22:51,932 INFO[ListenerClient]: Disconnected from whs:23344
2011-04-05 16:22:51,932 WARN  [TaskQueue]: No clients available to accept task of type 'COMSKIPTIMER'
2011-04-05 16:22:51,994 INFO[Listener]: Received connection from: /192.168.1.99:3716
2011-04-05 16:22:53,228 INFO[Listener]: Received connection from: /192.168.1.99:3718
2011-04-05 16:22:54,338 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:3718
2011-04-05 16:22:54,369 ERROR [Handler]: IOError: 192.168.1.99:3716
java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(Unknown Source)
	at java.net.SocketInputStream.read(Unknown Source)
	at java.io.ObjectInputStream$PeekInputStream.peek(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.refill(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.read(Unknown Source)
	at java.io.DataInputStream.readUnsignedShort(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readUTF(Unknown Source)
	at java.io.ObjectInputStream.readUTF(Unknown Source)
	at com.google.code.sagetvaddons.sjq.listener.Handler.run(Handler.java:62)
	at java.lang.Thread.run(Unknown Source)
2011-04-05 16:22:54,369 INFO[Listener]: Received connection from: /192.168.1.99:3720
2011-04-05 16:22:54,369 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.1.99:3720
2011-04-05 16:22:54,666 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:3720
2011-04-05 16:22:54,666 INFO[Listener]: Received connection from: /192.168.1.99:3723
2011-04-05 16:22:54,666 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.99:3723
2011-04-05 16:22:54,682 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-04-05 16:22:54,682 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:3723

[Slugger]

Seems you've got a massive backlog of tasks in the queue.

Go to http://192.168.0.1:8082/

Replace the IP with the IP where SJQ is installed.

On the form, enter this for the jdbc url:

jdbc:h2:tcp://localhost/plugins/sjq/sjq4

The id and password are both admin

When inside, enter this query in the input box:

select count(*) from queue where state in ('WAITING','RUNNING','STARTED')

Run it, what's the total?

Then run:

select count(*) from queue

Run that, what's the total? I suspect you're queue is backlogged severely, which is what would be causing all of this logging, etc.

Depending on what scripts you were running, if you recently updated them to the latest version then that backlog might start to finally go down. There were bugs in earlier versions of some of my groovy scripts where an invalid object id would cause a null pointer and then the response would be to just requeue and retry later. Later versions of those scripts treated the invalid ids as failures and just removed the task from the queue (by marking it failed).

[Slugger]

@KO

Please wrap log contents in [code] tags.

Also, how are you queuing this task? Why would so many be queued up immediately after wiping the db contents? Now, after re-reading your post a couple times, I'm more convinced you're queuing tasks incorrectly. Do any of them actually run as expected? Do any have metadata (look in the QUEUE_METADATA table when in the db)? It's definitely a misconfig somewhere, I'm just not sure where.

[K O]

There are 108 items in the queue, of which 2 are waiting, running, started.

What happens with all the RETURNED, SKIPPED, and COMPLETED items?

Those 108 items are queued over 3 days, not all at once. The events seem to kick off correctly, but some appear to get re-run indefinitely?

I'm getting the commercial skipping results I expect, but based on the size of the logs being generated and the memory getting all consumed on my sage server over a few days' time when I have SJQ4 enabled, I think I still have issues with my configuration or groovy scripts or both!

[K O]

Originally Posted by Slugger

Please wrap log contents in [code] tags.

Edited. Thanks! Didn't know that.

Originally Posted by Slugger

Also, how are you queuing this task? Why would so many be queued up immediately after wiping the db contents? Now, after re-reading your post a couple times, I'm more convinced you're queuing tasks incorrectly. Do any of them actually run as expected? Do any have metadata (look in the QUEUE_METADATA table when in the db)? It's definitely a misconfig somewhere, I'm just not sure where.

I've got 3 tasks, the first 2 are attached to the recording start event and do the same thing, but one looks for .ts files and one looks for .mpg files. The 3rd task is COMSKIPTIMER, which is run periodically with a cron timer (may not be using terminology correctly) that looks through all recordings and kicks off comskip events if no .edl files exist. I use this as the cleanup, since there are circumstances in which the first comskip won't execute correctly. Some reasons they don't start correctly would be the audio is corrupted in the beginning of the show, so comskip fails before it gets going, and more often, because there's a file change in the recording - typical behavior for the R5000 satellite recordings, and the new file doesn't get comskip'd because it doesn't trigger a Sage event. There is metadata in the queue_metadata table corresponding to the events that have been comskip'd.

COMSKIP1 GROOVY

boolean checkRecordingType = true; 
boolean checkForEdl = true;        
String edlType = "edl";           
boolean comskipLive = true;       



def idStr = SJQ4_METADATA.get("SJQ4_ID")
if(idStr == null || !idStr.matches("\\d+")) {
   println "SJQ4_ID is not present in metadata; marking task as SKIPPED!"
   return 2
}

Object mf = MediaFileAPI.GetMediaFileForID(Integer.parseInt(idStr));
File path = new File(SJQ4_METADATA.get("SJQ4_PATH"));
String fileName = SJQ4_METADATA.get("SJQ4_LAST_SEGMENT");
String fileType;
if(SJQ4_ARGS.length > 0)
   fileType = SJQ4_ARGS[0];
else
   fileType = null;

if(mf == null || path == null || path.getAbsolutePath().length() == 0 || fileName == null || fileName.length() == 0) {
   println("ERROR: Invalid environment data passed to scritpt!");
   return 2;
}

String edl = fileName.substring(0, fileName.lastIndexOf('.')) + "." + edlType;
if(new File(path, edl).exists()) {
   println("An edl already exists for this recording, skipping comskip!");
   println("Found '" + new File(path, edl).getAbsolutePath() + "'");
   return 2;
}

if(checkRecordingType && fileType != null && fileType.length() > 0 && !fileName.endsWith("." + fileType)) {
   println("Recording is not of specified type '" + fileType + "', skipping comskip!");
   return 2;
}

if(!comskipLive && MediaFileAPI.IsFileCurrentlyRecording(mf)) {
   println("Recording in progress, waiting...");
   return 1;
}

if (!comskipLive && MediaFileAPI.IsFileCurrentlyRecording(mf) && AiringAPI.IsNotManualOrFavorite(mf)) {
   println("LiveTV recording in progress, will not Comskip unless converted to manual recording.");
   return 1;
}


if (AiringAPI.IsNotManualOrFavorite(mf)) {
   return 2;
}

return 0;

TIMER EVENT COMSKIP GROOVY

def testMode = false
def mediaMask = "T" 
def taskIds = ["COMSKIP1", "COMSKIP2"]


def needsProcessing(Object mediaFile) {
    // This function could be written in a much more condensed manner, but I'm breaking it up for the sake of readability
    
    // So let's skip queuing this media file if it's live tv or an IR recording
    if(AiringAPI.IsNotManualOrFavorite(mediaFile))
        return false
    
    // Personally, I don't comskip until the recording is done, so don't queue up recordings in progress
    if(MediaFileAPI.IsFileCurrentlyRecording(mediaFile))
        return false

    // Let's also skip it if it's from a channel known not to have commercials (adjust the regex accordingly)
    //if(AiringAPI.GetAiringChannelName(mediaFile) =~ /HBO.*|M(?:HD){0,1}|WPBS|.*PPV.*/)
        //return false

    // Let's also skip it if there is already an edl file for the media file; adjust the extensions, if necessary        
    if(hasArtifacts(mediaFile, ["edl"])) // This function is defined at the bottom of the file
        return false
    
    // All our tests have passed so return true
    return true
}

/***** END CONFIG BLOCK *****/

/***** DO NOT MODIFY BELOW THIS LINE *****/

import com.google.code.sagetvaddons.sjq.network.ServerClient
import com.google.code.sagetvaddons.metadata.Factory
import org.apache.commons.io.FilenameUtils

def sc = !testMode ? new ServerClient() : null
MediaFileAPI.GetMediaFiles(mediaMask).each { mf ->
    if(needsProcessing(mf)) {
        if(!testMode)
            taskIds.each { id ->
                sc.addTask(id, Factory.getMap(mf))
            }
        else
            println "Would queue up '${MediaFileAPI.GetMediaTitle(mf)}' (${MediaFileAPI.GetMediaFileID(mf)}); skipped because test mode is TRUE"
    }
}
if(sc != null)
    sc.close()
return 1

// Returns true if any segment of the given media file has at least one artifact of any of the given artifact extensions; false otherwise
def hasArtifacts(Object mf, List exts) {
    for(def it : MediaFileAPI.GetSegmentFiles(mf)) {
        def absPath = it.getAbsolutePath()
        def dir = FilenameUtils.getFullPath(absPath)
        def base = FilenameUtils.getBaseName(absPath)
        for(def ext : exts) {
            def artifact = "${dir}${base}.$ext"
            if(Utility.IsFilePath(artifact))
                return true
        }
    }
    return false
}

[Slugger]

And exactly what directory is taking up all your space and how much?

The completed, skipped and failed tasks purge themselves from the db after 7, 1, and 21 days, respectively (configurable from SJQ plugin config screen in STV).

[K O]

Originally Posted by Slugger

And exactly what directory is taking up all your space and how much?

As of right now, C:\Program Files\SageTV\SageTV\plugins\sjq\sjq4.lobs.db is 200MB, and C:\Program Files\SageTV\SageTV\.lobs.db is 2.2GB.

That's in 3 days. When I deleted them a few days ago, the C:\Program Files\SageTV\SageTV\.lobs.db was 12GB after about 2 weeks, and my Windows Home Server was complaining that the C:\ drive was full since Windows Home Server only allocates 20GB to it.

Every single file in the C:\Program Files\SageTV\SageTV\.lobs.db folder has the same exact thing on every line, repeated every second, taking up hundreds of files named numerically. There are actually 12,000 log files all containing the exact same thing on every line just since 3 days ago:

=================================== Sun Apr 03 04:07:41 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties

[Slugger]

Originally Posted by K O

As of right now, C:\Program Files\SageTV\SageTV\plugins\sjq\sjq4.lobs.db is 200MB

This directory is completely managed by SJQ. You should never need to touch this. 200MB is a lot of logs, a lot! But it also is only 200MB compared to the 2.2GB because it is being managed and purged as expected.

C:\Program Files\SageTV\SageTV\.lobs.db is 2.2GB

This is obviously the problem. There are issues with the H2 client cachiing of LOB columns. I can't fix that. You will have to clean this up periodically if it continues to be a problem, there's no way around that. But...

Every single file in the C:\Program Files\SageTV\SageTV\.lobs.db folder has the same exact thing on every line, repeated every second, taking up hundreds of files named numerically. There are actually 12,000 log files all containing the exact same thing on every line just since 3 days ago:

=================================== Sun Apr 03 04:07:41 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties

The date header increases by only one second each time? If so, that's a problem, but confusing because even if a task were being run in a loop, there should be at least 8 seconds between each run (there is an 8 second delay in the queue processor). Maybe there's a bug in that logic, but that doesn't really matter for now.

Let's see your sjqagent.log file (plugins/sjq-agent/logs if running the plugin task client). Is it only certain times of the day when the task logs every second? There's some reason that task(s) are continuously running, we simply need to track it down and fix it. Are you only using one task client?

[K O]

Originally Posted by Slugger

The date header increases by only one second each time? If so, that's a problem, but confusing because even if a task were being run in a loop, there should be at least 8 seconds between each run (there is an 8 second delay in the queue processor). Maybe there's a bug in that logic, but that doesn't really matter for now.

I was mistaken about the every second.. it's every 30 seconds with a little bit of time shifting. It's pretty regular. Here's a sample, you can see the time stamps. There is roughly one 1MB file generated nearly every minute, or approximately 50-75 new 1MB files per hour.

==============================

===== Tue Apr 05 18:15:25 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:15:54 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:16:24 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:16:53 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:17:24 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:17:55 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:18:24 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:18:55 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:19:24 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:19:55 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:20:24 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties



==============================

===== Tue Apr 05 18:20:54 CDT 2011 =====

LOG4J: Configured Logging for: sagex-api using file: sagex-api.log4j.properties

Originally Posted by Slugger

Let's see your sjqagent.log file (plugins/sjq-agent/logs if running the plugin task client). Is it only certain times of the day when the task logs every second? There's some reason that task(s) are continuously running, we simply need to track it down and fix it. Are you only using one task client?

One task client, here's the last 15 minutes worth of the agent's log files. I'm using the standalone windows service agent.

2011-04-05 18:04:55,278 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:04:55,293 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:04:55,293 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:05:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:05:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:05:24,793 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:05:24,809 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:05:24,809 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:05:51,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:05:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:05:54,950 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:05:54,965 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:05:54,965 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:06:21,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:06:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:06:23,918 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:06:23,918 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:06:23,918 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:06:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:06:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:06:56,809 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:06:56,825 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:06:56,825 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:07:04,840 INFO  [Exe]: Received task 14366 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:07:04,840 INFO  [192_168_1_99-23347-14366]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:07:09,075 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:07:09,090 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:07:09,090 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14366
2011-04-05 18:07:21,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:07:21,668 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:07:25,606 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:07:25,622 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:07:25,622 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:07:51,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:07:51,668 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:07:55,043 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:07:55,059 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:07:55,059 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:08:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:08:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:08:25,606 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:08:25,622 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:08:25,622 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:08:51,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:08:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:08:55,418 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:08:55,434 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:08:55,434 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:09:21,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:09:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:09:25,059 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:09:25,075 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:09:25,075 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:09:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:09:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:09:55,184 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:09:55,200 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:09:55,200 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:10:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:10:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:10:25,278 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:10:25,293 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:10:25,293 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:10:51,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:10:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:10:55,668 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:10:55,684 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:10:55,684 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:11:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:11:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:11:25,575 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:11:25,590 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:11:25,590 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:11:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:11:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:11:55,309 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:11:55,325 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:11:55,325 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:12:21,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:12:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:12:25,106 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:12:25,106 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:12:25,106 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:12:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:12:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:12:55,512 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:12:55,528 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:12:55,528 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:13:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:13:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:13:25,075 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:13:25,090 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:13:25,090 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:13:51,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:13:51,668 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:13:55,247 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:13:55,278 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:13:55,278 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:14:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:14:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:14:25,872 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:14:25,887 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:14:25,887 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:14:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:14:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:14:55,450 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:14:55,465 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:14:55,465 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:15:21,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:15:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:15:25,247 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:15:25,262 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:15:25,262 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:15:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:15:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:15:54,997 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:15:55,012 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:15:55,012 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:16:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:16:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:16:24,418 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:16:24,434 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:16:24,434 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:16:51,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:16:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:16:54,028 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:16:54,043 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:16:54,043 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:17:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:17:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:17:25,075 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:17:25,090 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:17:25,090 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:17:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:17:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:17:55,731 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:17:55,747 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:17:55,747 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:18:21,668 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:18:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:18:24,684 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:18:24,700 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:18:24,700 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:18:51,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:18:51,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]
2011-04-05 18:18:55,137 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:18:55,153 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-04-05 18:18:55,153 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-14191
2011-04-05 18:19:21,684 INFO  [Exe]: Received task 14191 of type 'COMSKIPTIMER' from 192.168.1.99:23347...
2011-04-05 18:19:21,684 INFO  [192_168_1_99-23347-14191]: Starting process runner for: Task[id=COMSKIPTIMER, reqRes=0, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=c:/comskip/comskip.exe, exeArgs=, test=c:/sjqagent/comskip_timer_test.groovy, testArgs=]

[Slugger]

Ok, we're getting somewhere...

First, you only run the single Win service task client and no others? If so, are you looking at the logs from the UI a lot?

14191 is being constantly reassigned. This task should never be returned to the queue. Show me your config setup for this task, please.