Plugin: Sage Job Queue (SJQ) v3

[ohpleaseno]

WHS client is running now, thanks!

My Win 7 box doesn't even show up on the GUI. I followed the directions for NT-service and it shows up in the Services panel on the box. How can I troubleshoot that? When I try to start it from within services, it gives me an error

[Slugger]

Go to the directory where you installed the client. In there is a logs directory that has a wrapper.log file. Look in there. My initial guess is that the service cannot find the path to your Java JRE on the WHS box, but the wrapper.log should give you the complete answer.

[ohpleaseno]

Do I need to let it write it's own sjqc.properties?

Here are the last few dozen lines

STATUS | wrapper  | 2009/11/25 12:03:49 | <-- Wrapper Stopped
STATUS | wrapper  | 2009/11/25 12:06:20 | --> Wrapper Started as Service
STATUS | wrapper  | 2009/11/25 12:06:20 | Java Service Wrapper Community Edition 3.3.1
STATUS | wrapper  | 2009/11/25 12:06:20 |   Copyright (C) 1999-2008 Tanuki Software, Inc.  All Rights Reserved.
STATUS | wrapper  | 2009/11/25 12:06:20 |     http://wrapper.tanukisoftware.org
STATUS | wrapper  | 2009/11/25 12:06:20 | 
STATUS | wrapper  | 2009/11/25 12:06:21 | Launching a JVM...
INFO   | jvm 1    | 2009/11/25 12:06:23 | WrapperManager: Initializing...
INFO   | jvm 1    | 2009/11/25 12:06:23 | SJQ Task Client v3.0.0.655
INFO   | jvm 1    | 2009/11/25 12:06:23 | Using 'C:/sjqc/sjqc.properties' as location for configuration file...
INFO   | jvm 1    | 2009/11/25 12:06:23 | Unable to create configuration directory [C:\sjqc\sjqc.properties]
STATUS | wrapper  | 2009/11/25 12:06:25 | <-- Wrapper Stopped
STATUS | wrapper  | 2009/11/25 13:21:14 | --> Wrapper Started as Service
STATUS | wrapper  | 2009/11/25 13:21:14 | Java Service Wrapper Community Edition 3.3.1
STATUS | wrapper  | 2009/11/25 13:21:14 |   Copyright (C) 1999-2008 Tanuki Software, Inc.  All Rights Reserved.
STATUS | wrapper  | 2009/11/25 13:21:14 |     http://wrapper.tanukisoftware.org
STATUS | wrapper  | 2009/11/25 13:21:14 | 
STATUS | wrapper  | 2009/11/25 13:21:14 | Launching a JVM...
INFO   | jvm 1    | 2009/11/25 13:21:15 | WrapperManager: Initializing...
INFO   | jvm 1    | 2009/11/25 13:21:15 | SJQ Task Client v3.0.0.655
INFO   | jvm 1    | 2009/11/25 13:21:15 | Using 'C:/sjqc/sjqc.properties' as location for configuration file...
INFO   | jvm 1    | 2009/11/25 13:21:15 | Unable to create configuration directory [C:\sjqc\sjqc.properties]
STATUS | wrapper  | 2009/11/25 13:21:17 | <-- Wrapper Stopped

[Slugger]

Did you edit wrapper.conf? If so, you only point it to the dir where it should write the props file, don't specify the file as well, so you just want to point it to C:/sjqc

[ohpleaseno]

that did it. Thanks!

[gveres]

Originally Posted by evilpenguin

Here's my setup:

Ruleset: Live Comskip and run Mediashink on any recording older than 30 days

Hey EP, is that correct that you run comskip while the recording is happening? Comskip can handle that when it gets caught up to the recording?

[razrsharpe]

Originally Posted by gveres

Hey EP, is that correct that you run comskip while the recording is happening? Comskip can handle that when it gets caught up to the recording?

Yes, to both. I start comskip about 30sec to 1 min after a recording... never misses a beat. There is a comskip option that outputs to the .edl file as it goes in the comskip.ini file that needs to be enabled... not at home though so cant check what it is.

[evilpenguin]

Originally Posted by razrsharpe

not at home though so cant check what it is.

live_tv=1	; set to 1 if you use parallelprocessing and need the output while recording

Works great, it'll just keep going until the file stops getting bigger.

[gveres]

Thank you very much guys. I will put that in place tonight.

Greg

[nyplayer]

Slugger,

This happens at least once a day.... I do not have sqlite3 installed. Haven't had time to take down the server.

2009-11-27 07:02:50,656 ERROR [DataStore]: SQL error
java.sql.SQLException: database is locked
	at org.sqlite.DB.throwex(DB.java:288)
	at org.sqlite.DB.executeBatch(DB.java:236)
	at org.sqlite.PrepStmt.executeBatch(PrepStmt.java:83)
	at com.google.code.sagetvaddons.sjq.server.DataStore.flushLogs(DataStore.java:1049)
	at com.google.code.sagetvaddons.sjq.server.SJQServlet.doPost(SJQServlet.java:267)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:230)
	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:326)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:879)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)

[ohpleaseno]

I probably should have asked this question over here...

http://forums.sagetv.com/forums/show...&postcount=331

What I asked there is if there is a way for SJQ to open the mediashrink console window (or any window) when it starts a job so that I can monitor the progress.

[Slugger]

Originally Posted by nyplayer

Slugger,

This happens at least once a day.... I do not have sqlite3 installed. Haven't had time to take down the server.

2009-11-27 07:02:50,656 ERROR [DataStore]: SQL error
java.sql.SQLException: database is locked
	at org.sqlite.DB.throwex(DB.java:288)
	at org.sqlite.DB.executeBatch(DB.java:236)
	at org.sqlite.PrepStmt.executeBatch(PrepStmt.java:83)
	at com.google.code.sagetvaddons.sjq.server.DataStore.flushLogs(DataStore.java:1049)
	at com.google.code.sagetvaddons.sjq.server.SJQServlet.doPost(SJQServlet.java:267)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:230)
	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:326)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:879)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)

I need you to look in the SJQ server logs and tell me if a LogCleaner process started at around the same time of this error. The error occurred at 2009-11-27 07:02:50 so please check the logs to see if a LogCleaner process started a few seconds before this error. I also need to know how long that LogCleaner took to complete. If it is a LogCleaner process that's locking your db again then the issue is ticket 98 and a proper fix isn't easy and it's also going to be time consuming. If you confirm that today, I might be able to try a temp fix before the weekend starts, but I need to know if it's the LogCleaner process that is constantly locking your db file.

[nyplayer]

Slugger,

I believe this is when it actually locked ... that error above was when a scheduled loader ran.

2009-11-26 22:03:41,984 INFO  [LogCleaner]: LogCleaner instance finished [3094ms]
2009-11-26 22:03:42,546 INFO  [DataStore]: Flushed 35 log message(s) in 3390ms
2009-11-26 22:03:42,578 ERROR [DataStore]: SQL error
java.sql.SQLException: database is locked
	at org.sqlite.DB.throwex(DB.java:288)
	at org.sqlite.DB.executeBatch(DB.java:236)
	at org.sqlite.PrepStmt.executeBatch(PrepStmt.java:83)
	at com.google.code.sagetvaddons.sjq.server.DataStore.flushLogs(DataStore.java:1049)
	at com.google.code.sagetvaddons.sjq.server.SJQServlet.doPost(SJQServlet.java:267)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:230)
	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:326)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:879)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)
2009-11-26 22:03:46,578 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 22:03:46,593 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 22:03:46,593 INFO  [ClientParser]: MAPPING: \\192.168.2.155\j$\sageuncj => j:\sageuncj

[nyplayer]

2009-11-26 07:23:53,906 INFO  [FileCleaner]: FileCleaner instance started
2009-11-26 07:23:53,906 ERROR [FileCleaner]: File cleaner settings cannot be empty!
2009-11-26 07:23:53,906 INFO  [TvArchiver]: Attempting to copy 'N:\sagen\LawOrder-Entrapment-4862348-0.mp4.tmp' to '\\NYPLAYER\t$\sageunct'...
2009-11-26 07:23:57,265 ERROR [DataStore]: SQL error
java.sql.SQLException: database locked
	at org.sqlite.DB.execute(DB.java:270)
	at org.sqlite.DB.executeUpdate(DB.java:281)
	at org.sqlite.PrepStmt.executeUpdate(PrepStmt.java:77)
	at com.google.code.sagetvaddons.sjq.server.DataStore.setSetting(DataStore.java:880)
	at com.google.code.sagetvaddons.sjq.server.SystemMessageQueueLoader.run(SystemMessageQueueLoader.java:68)
	at java.lang.Thread.run(Unknown Source)
2009-11-26 07:23:57,281 WARN  [SJQServlet]: Checking client '192.168.0.2': 100 resources free.
2009-11-26 07:23:57,406 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,406 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,406 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,406 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,421 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,421 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,421 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:57,437 WARN  [SJQServlet]: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings
2009-11-26 07:23:59,062 INFO  [LogCleaner]: LogCleaner instance finished [5250ms]
2009-11-26 07:23:59,140 INFO  [DataStore]: Flushed 1 log message(s) in 1734ms
2009-11-26 07:23:59,359 INFO  [DataStore]: Flushed 1 log message(s) in 1953ms

[Slugger]

2009-11-26 07:23:59,062 INFO [LogCleaner]: LogCleaner instance finished [5250ms]

That is the problem. Your LogCleaner is taking way more time than it ever should to clean up. It's a slow, brute force process, but it should never take 5+ seconds to complete. The SQLite driver will only wait upto 3 seconds for the database to become unlocked and so that's the problem. How large is your sjq.sqlite file? Do the tasks you run in SJQ produce a lot of output?

A proper fix is not coming any time soon - it's going to take some thought to get it done right. A temp fix could be thrown in that may reduce the likelihood of this error scenario occurring. If I'm able to get away from work early today I'll try to whip up something before I head out for the evening, otherwise it'll have to wait for tomorrow.

[nyplayer]

Slugger,

My sqlite db is 3,080kb. I am running in debug mode maybe that is why. I have created a simple batch file that looks at the logs and if it sees db is locked it will restart sjq.... so I am not in dire need of a fix.

[jakfech]

I am having the same issue. My sjq.sqlite file is 13MB and it takes 9s for FileCleaner to run. However, now that I know what the cause is I'm not really worried. As long as the server and clients continue to function it's alright if there is some disruption.

I am running custom scripts that do cut down the output from ComSkip and MEncoder but not enough to ever avoid this issue (my scripts depend on there being output about every 10s as sort of a keep alive indicator).

[jakfech]

I think I found something new; if a recording gets split into multiple files (say the machine restarts in the middle of a recording), Sage will list the two files as a single recording with both files listed in the recordings media info and stitch them together during playback. I am in the process of switching from Beyond and I find this to be a much better way of handling this. However, this leads to headaches in how to treat these multiple parts. Right now SJQ (forgive me, I'd post specifics but I forgot to grab my client logs before they were overwritten) sends just the first file to the client. SJQ needs to be able to pass all of the parts of the recording to a client either as a semi-colon separated list (in a new %X% variable) or call the client with each file one at a time. The latter being easier for most programs to handle though a quick front end script could handle the %X% for most programs.

Though I'm not entirely sure how Sage will handle certain tasks on split recordings. There's a good chance that if I were to replace each of the recorded MPGs with an AVI that Sage would still see these as the same pieces as before, but what about ComSkip? If I have recording1-12345-0.mpg and recording1-12345-1.mpg plus recording1-12345-0.edl and recording1-12345-1.mpg how will ComSkip Playback (which I use) or SageMC handle this? It will probably work but I am curious if someone knows for sure.

[Slugger]

Originally Posted by jakfech

I think I found something new; if a recording gets split into multiple files (say the machine restarts in the middle of a recording), Sage will list the two files as a single recording with both files listed in the recordings media info and stitch them together during playback. I am in the process of switching from Beyond and I find this to be a much better way of handling this. However, this leads to headaches in how to treat these multiple parts. Right now SJQ (forgive me, I'd post specifics but I forgot to grab my client logs before they were overwritten) sends just the first file to the client. SJQ needs to be able to pass all of the parts of the recording to a client either as a semi-colon separated list (in a new %X% variable) or call the client with each file one at a time. The latter being easier for most programs to handle though a quick front end script could handle the %X% for most programs.

Though I'm not entirely sure how Sage will handle certain tasks on split recordings. There's a good chance that if I were to replace each of the recorded MPGs with an AVI that Sage would still see these as the same pieces as before, but what about ComSkip? If I have recording1-12345-0.mpg and recording1-12345-1.mpg plus recording1-12345-0.edl and recording1-12345-1.mpg how will ComSkip Playback (which I use) or SageMC handle this? It will probably work but I am curious if someone knows for sure.

SJQ should be calling the task multiple times, once for each file segment. So if a recording was split into 2 parts, SJQ should pass file-0.mpg to the first command then run the command again with file-1.mpg. If it's not, it's a regression (this definitely used to work like this). Note that if the task failed for an earlier segment then the remaining segments will not be processed, but instead the task is just halted and marked as failed.

[Slugger]

Originally Posted by jakfech

I am having the same issue. My sjq.sqlite file is 13MB and it takes 9s for FileCleaner to run. However, now that I know what the cause is I'm not really worried. As long as the server and clients continue to function it's alright if there is some disruption.

I am running custom scripts that do cut down the output from ComSkip and MEncoder but not enough to ever avoid this issue (my scripts depend on there being output about every 10s as sort of a keep alive indicator).

A possible fix came to me while driving home tonight... a lot easier to implement than my original idea. Still need to find a few hours to sit down and implement it, but feeling pretty good about it. Maybe this weekend or early next week I'll get a chance to work on it.

Though I am concerned why some people's LogCleaner is taking on the order of 5-10 seconds to complete. I am not seeing this at all:

2009-11-27 16:30:12,126 INFO  [LogCleaner]: LogCleaner instance finished [15ms]
2009-11-27 17:00:12,072 INFO  [LogCleaner]: LogCleaner instance finished [16ms]
2009-11-27 17:30:12,112 INFO  [LogCleaner]: LogCleaner instance finished [0ms]
2009-11-27 18:00:12,104 INFO  [LogCleaner]: LogCleaner instance finished [31ms]
2009-11-27 19:30:12,129 INFO  [LogCleaner]: LogCleaner instance finished [0ms]
2009-11-27 22:30:12,006 INFO  [LogCleaner]: LogCleaner instance finished [31ms]
2009-11-28 00:00:12,143 INFO  [LogCleaner]: LogCleaner instance finished [15ms]
2009-11-28 00:30:12,078 INFO  [LogCleaner]: LogCleaner instance finished [0ms]
2009-11-28 02:00:12,009 INFO  [LogCleaner]: LogCleaner instance finished [16ms]

If I could reproduce the issue it would be a lot easier to hopefully track down, but I'll give my idea a go when I get a chance and hopefully that leads to something good.